How To Write Unit Tests For Logging
Tags: unittests, tdd, testing, softwaredesign
Published: 2020-11-11 11:29:57

Once in a while I get asked the question whether one should write [solitary tests](https://principal-it.eu/2019/10/taxonomy-of-tests/) for logging functionality. My answer to this question is the typical consultant answer: “It depends”. In essence, logging is an infrastructure concern. The end result is log data that is being written to a resource which is external to an application. Usually the generated data ends up in a file, a database or it might even end up in a cloud service.

Because logging crosses the process boundary of an application, it is more useful to write [sociable tests](https://principal-it.eu/2019/10/taxonomy-of-tests/) to verify this particular functionality. It doesn’t make sense to use solitary tests in this particular case.

That being said, there are situations where business requirements explicitly state that logging should be a part of the interface of an application. In this situation, the intent of logging should be expressed explicitly by the code which in turn should also be exercised by solitary tests. The excellent book [Growing Object Oriented Software Guided By Tests](https://bit.ly/tdd-goos2), written by Steve Freeman and Nat Pryce, mentions that there are generally two separate types of logging:

- Support logging
- Diagnostic logging

A support log contains messages that are intended for those that perform operational activities. These messages are used to determine whether the system behaves correctly or not. The log level for these messages is usually of type _error_ or _info_.

A diagnostic log on the other hand holds messages that are targeted towards software developers. These messages provide valuable insights into the details of a running system. The log level for these messages is usually of type _debug_ or _trace_.

Given these two types of logging, the basic idea is that code which expresses the intent of support logging should be exercised by solitary tests. Code statements that initiate diagnostic logging are usually not covered by tests.

Let’s have a look at an example that demonstrates both support and diagnostic logging in action.

```csharp
public class ExpenseSheetController : Controller
{
    private readonly ICommandHandler<CreateExpenseSheet> _commandHandler;
    private readonly ISupportNotifier _supportNotifier;

    public ExpenseSheetController(ICommandHandler<CreateExpenseSheet> commandHandler,
                                  ISupportNotifier supportNotifier)
    {
        _commandHandler = commandHandler;
        _supportNotifier = supportNotifier;
    }
    
    [HttpPost]
    [ServiceFilter(typeof(PerformanceTracing))]
    public IActionResult Create(CreateExpenseSheetFormModel formModel)
    {
        try
        {
            var command = new CreateExpenseSheet(Guid.NewGuid(), formModel.EmployeeId);
            _commandHandler.Handle(command);
        }
        catch(Exception ex)
        {
            _supportNotifier.ErrorDuringExpenseSheetCreation(ex, formModel.EmployeeId);
            return BadRequest();
        }
        
        _supportNotifier.ExpenseSheetCreated(formModel.EmployeeId);
        return Ok();
    }
}

```

Here we have the implementation of a controller that can receive a request for creating a new expense sheet. Notice that the constructor of this controller class expects an instance of the _ISupportNotifier_ interface. This dependency is being used by the implementation of the _Create_ method for logging an error when an exception occurs. It is also used for logging when an expense sheet has been successfully created.

This is how the implementation of the _SupportNotifier_ looks like.

```csharp
public class SupportNotifier : ISupportNotifier
{
    private readonly ILogger<SupportNotifier> _logger;

    public SupportNotifier(ILogger<SupportNotifier> logger)
    {
        _logger = logger;
    }
    
    public void ExpenseSheetCreated(Guid employeeId)
    {
        _logger.LogInformation("Expense sheet created for employee with ID '{employeeId}'.");
    }

    public void ErrorDuringExpenseSheetCreation(Exception ex, Guid employeeId)
    {
        _logger.LogError(ex, $"Unable to create a new expense sheet for employee with ID '{employeeId}'");
    }
}

```

This code demonstrates that support logging uses log levels _error_ or _info_ depending on the context. Verifying the code of the _SupportNotifier_ class itself can be done by using sociable tests. It’s not a good idea to write solitary tests for the _SupportNotifier_ class. This would imply that a test double should be used as an instance of _ILogger_. As we already touched on in a [previous blog post](/2020/05/test-double-heuristics/), it’s much better to avoid using test doubles for types that you don’t own. In this particular case it would even be quite hard to do as the _Logxx_ methods of _ILogger_ are actually extension methods and not regular methods.

Let’s have a look at the tests for the _ExpenseSheetController_.

```csharp
[Specification]
public class When_handling_a_request_for_creating_a_new_expense_sheet
{
    [Establish]
    public void Context()
    {
        var commandHandler = Substitute.For<ICommandHandler<CreateExpenseSheet>>();
        _supportNotifier = Substitute.For<ISupportNotifier>();

        _sut = new ExpenseSheetController(commandHandler, _supportNotifier);
    }

    [Because]
    public void Of()
    {
        var formModel = new CreateExpenseSheetFormModel 
        { 
            EmployeeId = new Guid("94EDE8F3-9675-4DD7-A18F-E37B1F323699") 
        };

        _sut.Create(formModel);
    }
    
    [Observation]
    public void Then_it_should_notify_support()
    {
        _supportNotifier.Received()
            .ExpenseSheetCreated(new Guid("94EDE8F3-9675-4DD7-A18F-E37B1F323699"));
    }

    private ExpenseSheetController _sut;
    private ISupportNotifier _supportNotifier;
}

[Specification]
public class When_an_error_occurs_while_handling_a_request_for_creating_a_new_expense_sheet
{
    [Establish]
    public void Context()
    {
        _supportNotifier = Substitute.For<ISupportNotifier>();
        _exception = new InvalidOperationException("Meltdown");
        
        var commandHandler = Substitute.For<ICommandHandler<CreateExpenseSheet>>();
        commandHandler.WhenForAnyArgs(ch => ch.Handle(null))
            .Throw(_exception);
        
        _sut = new ExpenseSheetController(commandHandler, _supportNotifier);
    }
    
    [Because]
    public void Of()
    {
        var formModel = new CreateExpenseSheetFormModel 
        { 
            EmployeeId = new Guid("D1067157-5C73-4140-9D29-0FE5C1C4C2FB") 
        };

        _sut.Create(formModel);
    }
    
    [Observation]
    public void Then_it_should_notify_support_that_a_new_expense_sheet_has_been_created()
    {
        _supportNotifier.Received()
            .ErrorDuringExpenseSheetCreation(_exception, 
                new Guid("D1067157-5C73-4140-9D29-0FE5C1C4C2FB"));
    }
    
    private ExpenseSheetController _sut;
    private ISupportNotifier _supportNotifier;
    private Exception _exception;
}

```

These tests verify whether support logging occurs when an expense sheet has been created or when an exception gets raised. This way we express the intent of the operational requirements.

Notice that controller method has been decorated with a _ServiceFilter_ attribute.

```csharp
[HttpPost]
[ServiceFilter(typeof(PerformanceTracing))]
public IActionResult Create(CreateExpenseSheetFormModel formModel)
{
    ...
}

```

By applying this attribute, the _PerformanceTracing_ action filter is being registered to surround the execution of the controller method. Let’s have a look at the implementation of this action filter.

```csharp
public class PerformanceTracing : ActionFilterAttribute
{
    private readonly ILogger<PerformanceTracing> _logger;
    private readonly Stopwatch _stopWatch;

    public PerformanceTracing(ILogger<PerformanceTracing> logger)
    {
        _logger = logger;
        _stopWatch = new Stopwatch();
    }

    public override void OnActionExecuting(ActionExecutingContext context)
    {
        _stopWatch.Start();
    }

    public override void OnActionExecuted(ActionExecutedContext context)
    {
        _stopWatch.Stop();

        var controllerName = context.Controller.GetType().Name;
        var controllerActionName = context.ActionDescriptor.DisplayName;
        
        _logger.LogTrace($"Action '{controllerActionName}' of controller {controllerName} executed in " + 
            $"{_stopWatch.ElapsedMilliseconds} ms.");
    }
}

```

This implementation is a nice example of diagnostic logging. The action filter measures the execution time of a controller method and logs the result. Notice that we’re injecting the _ILogger_ interface directly into the constructor. By registering the _PerformanceTracing_ action filter using the _ServiceFilter_ attribute, we ensure that an instance of _ILogger_ gets resolved and properly injected. We didn’t provide any tests for this implementation.

I think it’s useful to consider support logging and diagnostic logging as two separate concepts, even though they quite often use the same mechanisms under the hood.