Blog

Once in a while I get asked the question whether one should write solitary 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, which is written to a resource that 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 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, 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.

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.

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

[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 is being created or when an exception gets raised. This way we express the intent of the operational requirements.

Notice also that the controller method has been decorated with a ServiceFilter attribute.

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

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.

Jan Van Ryswyck

Thank you for visiting my blog. I’m a professional software developer since Y2K. A blogger since Y2K+5. Provider of training and coaching in XP practices. Curator of the Awesome Talks list. Past organizer of the European Virtual ALT.NET meetings. Thinking and learning about all kinds of technologies since forever.