Adding Logging to Our Controllers

Let's use this opportunity to review logging from the previous course:

Logging is a common and critical part of modern applications. It helps in tracking the flow of the application, troubleshooting issues, and monitoring the overall health of the system.

In .NET, logging is built into the framework and can be configured to log information from various parts of your application.

Logging Overview

In .NET, logging is handled through the ILogger<T> interface, which can be injected into any class. This provides a unified API to write log messages at different levels, such as Information, Warning, Error, and more.

ILogger

ILogger<T> is the core logging interface in .NET. The T in ILogger<T> refers to the class where the logger is injected, helping to provide context about which part of the application is generating log messages.

public class MyService
{
    private readonly ILogger<MyService> _logger;

    public MyService(ILogger<MyService> logger)
    {
        _logger = logger;
    }

    public void DoWork()
    {
        _logger.LogInformation("Starting work...");
    }
}

In this example, the logger is injected via constructor injection and is used to log an informational message.

Log Levels

.NET supports several logging levels, each representing the severity of the message being logged:

Trace: Typically only useful for debugging purposes. Used to log very detailed information about the flow of the application. (e.g. "Starting DoWork method")
Debug: Information useful for debugging during development. (e.g. "DoWork processed employee 123456")
Information: General application flow information. (e.g. "DoWork method completed successfully")
Warning: Something unexpected happened, but the application can still function correctly - usually to call out issues with the application your code handled correctly, but may need investigation. (e.g. "FileNotFoundException for file log.txt, but continued processing")
Error: An error occurred, and the application might not be able to function as expected. (e.g. "Failed to connect to database")
Critical: A critical failure that requires immediate attention. (e.g. "Application is shutting down due to unrecoverable error")

Example of logging at different levels:

public void DoWork()
{
    _logger.LogTrace("This is a trace log.");
    _logger.LogDebug("This is a debug log.");
    _logger.LogInformation("This is an informational log.");
    _logger.LogWarning("This is a warning log.");
    _logger.LogError("This is an error log.");
    _logger.LogCritical("This is a critical log.");
}

You can find the rest of the materials on logging (logging to files, logging levels, filtering logging, etc.) in the previous course.

Let's go ahead and implement logging into our EmployeesController class:

public class EmployeesController : BaseController
{
    private readonly IRepository<Employee> _repository;
    private readonly ILogger<EmployeesController> _logger;

    public EmployeesController(IRepository<Employee> repository, ILogger<EmployeesController> logger)
    {
        _repository = repository;
        _logger = logger;
    }

Note the generic argument for the ILogger<T> is the controller class name. This helps to provide context about which part of the application is generating log messages.

Let's add logging to our UpdateEmployee method:

[HttpPut("{id}")]
public IActionResult UpdateEmployee(int id, [FromBody] UpdateEmployeeRequest employeeRequest)
{
    _logger.LogInformation("Updating employee with ID: {EmployeeId}", id);

    var existingEmployee = _repository.GetById(id);
    if (existingEmployee == null)
    {
        _logger.LogWarning("Employee with ID: {EmployeeId} not found", id);
        return NotFound();
    }

    _logger.LogDebug("Updating employee details for ID: {EmployeeId}", id);
    existingEmployee.Address1 = employeeRequest.Address1;
    existingEmployee.Address2 = employeeRequest.Address2;
    existingEmployee.City = employeeRequest.City;
    existingEmployee.State = employeeRequest.State;
    existingEmployee.ZipCode = employeeRequest.ZipCode;
    existingEmployee.PhoneNumber = employeeRequest.PhoneNumber;
    existingEmployee.Email = employeeRequest.Email;

    try
    {
        _repository.Update(existingEmployee);
        _logger.LogInformation("Employee with ID: {EmployeeId} successfully updated", id);
        return Ok(existingEmployee);
    }
    catch (Exception ex)
    {
        _logger.LogError(ex, "Error occurred while updating employee with ID: {EmployeeId}", id);
        return StatusCode(500, "An error occurred while updating the employee");
    }
}

Let's talk about a few things here.

Note the use of structured logging with the {EmployeeId} placeholder. In a logging system, we can use that as a field we can search on when finding relevant logs.
We can log exceptions and other details to provide more context about the error and where it occurred.

Pretty simple, and pretty powerful for making your systems more observable.

Ensuring logging is happening during testing

We can even go so far as to assert that logging is happening in our tests if we wanted to. Here's an example sort of implementation:

[Fact]
public async Task UpdateEmployee_LogsAndReturnsOkResult()
{
    // Arrange
    var loggerMock = new Mock<ILogger<EmployeesController>>().SetupAllProperties();
    var repositoryMock = new Mock<IEmployeeRepository>();
    var controller = new EmployeesController(loggerMock.Object, repositoryMock.Object);

    var employeeId = 1;
    var updateRequest = new UpdateEmployeeRequest { FirstName = "John", LastName = "Doe" };

    repositoryMock.Setup(r => r.GetById(employeeId)).Returns(new Employee { Id = employeeId });

    // Act
    var result = controller.UpdateEmployee(employeeId, updateRequest);

    // Assert
    Assert.IsType<OkObjectResult>(result);
    
    loggerMock.VerifyLog(logger => logger.LogInformation("Updating employee with ID: {EmployeeId}", employeeId));
    loggerMock.VerifyLog(logger => logger.LogInformation("Employee with ID: {EmployeeId} successfully updated", employeeId));
}

What in the heck is going on here?

We're using the Moq library to create a mock logger. This basically is a fake object that understands when certain methods are called.
We're using ILogger.Moq extension method to verify that the LogInformation method was called with the expected arguments. (Why use a separate library? We'd otherwise have to verify using ILogger.Log, and that'd be a pain.)

🌶️🌶️🌶️ Would I bother doing this? Yes, in the case where a business-critical process needs to log and I really want to make sure that behavior never changes. I don't really do this most of the time though.

← Previous Next →