Cómo hacer mock de ILogger en .Net Core 3.x durante las pruebas

Este mes he estado trabajando en un nuevo proyecto para un cliente que consiste en un servicio totalmente desatendido. Como servicio desatendido que es necesita un sistema de logging muy integrado de modo que haya toda la información posible en caso de fallo porque corre en equipos de difícil acceso. Funcionalidad a funcionalidad voy añadiendo las pruebas al código y me encuentro con una no muy agradable sorpresa… Los cambios en las clases de .Net Core 3 hacen que ILogger no se pueda mockear, al menos no a simple vista…

Por dar algo de contexto, el servicio lo he implementado con un Worker Service de .Net Core 3.1 por lo que la opción natural es registrar el logger dentro de la infraestructura de .Net Core 3.1 a través de ILogger y utiliza Entity Framework Core Code First.

¿Cómo se hacia mock de ILogger en .Net Core 2.x?

Para poder hacer las pruebas sobre código que utiliza ILogger teníamos (y tenemos en .Net Core 3.x) una implementación genérica que no hace nada para poder hacer las pruebas. Esta implementación es NullLogger y gracias a ella las pruebas van a poder lanzarse aunque el logger no haga nada. Si por el contrario necesitamos hacer algo sobre el logger, sea una configuración de callback para loguear a través de la consola de runner o simplemente verificaciones sobre los mensajes, vamos a tener que hacer nuestro propio mock.

Pese a que no era algo especialmente sencillo, hacer un mock de ILogger en .Net Core 2.x era posible sin tener que implementar código extra. La interfaz ILogger tiene entre muchos métodos de extensión, un método con una firma así:

public void Log<TState> (LogLevel logLevel, EventId eventId, TState state, Exception exception, Func<TState,Exception,string> formatter);

Sobre esta interfaz, el tipo genérico con el que se llama a esta interfaz es ‘FormattedLogValues‘. Sabiendo esta información se puede hacer un mock perfectamente con librerías como por ejemplo Moq sin mucho esfuerzo:

var logger = Mock.Of<ILogger<Program>>();
//Configuración
Mock.Get(logger).Setup(
           m => m.Log(
           It.IsAny<LogLevel>(),
           It.IsAny<EventId>(),
           It.IsAny<FormattedLogValues>(),
           It.IsAny<Exception>(),
           It.IsAny<Func<object, Exception, string>>()
           )
      ).Callback(/*Callback*/);
//Verificación
Mock.Get(logger).Verify(
           m => m.Log(
           It.IsAny<LogLevel>(),
           It.IsAny<EventId>(),
           It.IsAny<FormattedLogValues>(),
           It.IsAny<Exception>(),
           It.IsAny<Func<object, Exception, string>>()
           )
      );

El código es perfectamente funcional y con el se pueden escribir cualquier requisito para las pruebas.

¿Y por qué no se puede en .Net Core 3.x?

Si como comentábamos hace poco la interfaz no ha cambiado, y los métodos no han cambiado, ¿dónde está el problema? ¿Si pongo ese mismo código en mis pruebas porque no va a funcionar? Pues el problema está en que entre .Net Core 2 y 3 han cambiado algunas clases y estructuras, entre ellas ‘FormattedLogValues’ que ha pasado de ser pública a ser interna.

Esto hace que si ponemos el mismo código, pero utilizando las versiones de los paquetes para .Net Core 3.x, tengamos un error como este:

Si bien es cierto que los frameworks de mocking se adaptan para dar el mejor servicio posible ante estos cambios, no siempre son suficientes. Por ejemplo, para la parte de verificación Moq ya tiene una solución para reemplazar la prueba y es tan simple como esto:

Mock.Get(logger).Verify(
                  log => log.Log(
                    It.IsAny<LogLevel>(),
                    It.IsAny<EventId>(),
                    It.IsAny<It.IsAnyType>(),
                    It.IsAny<Exception>(),
                    (Func<It.IsAnyType, Exception, string>)It.IsAny<object>()),
                  Times.Once);

¿Cómo hacer mock de ILogger en .Net Core 3.x?

En mi caso concreto esta funcionalidad de verificación no fue suficiente ya que estaba teniendo problemas con las pruebas en el entorno de integración que no se replicaban en ninguna otra máquina. Para poder aprovechar toda la información de log que el propio código genera necesitaba relanzar el logger hacia la consola del runner de xUnit.

En versiones anteriores de .Net Core me hubiese valido utilizar un callback del método ‘Log’, pero con el cambio de ‘FormattedLogValues’ no es una opción. Precisamente por eso he tenido que hacer mi propia implementación de ILogger basada en la del NullLogger, pero con los extras bajo el capó:

public class SpyLogger<T> : ILogger<T>
{
    private readonly ITestOutputHelper _outputHelper;

    public SpyLogger(ITestOutputHelper outputHelper)
    {
        _outputHelper = outputHelper;
    }

    public IDisposable BeginScope<TState>(TState state)
    {
        return NullScope.Instance;
    }

    public bool IsEnabled(LogLevel logLevel)
    {
        return true;
    }

    public void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Exception exception, Func<TState, Exception, string> formatter)
    {
        _outputHelper.WriteLine($"{DateTime.Now.TimeOfDay}--{typeof(T).Name}-->{state}");
    }
}
internal class NullScope : IDisposable
{
    public static NullScope Instance { get; } = new NullScope();

    private NullScope()
    {
    }
    public void Dispose()
    {
    }
}

En este código las cosas importantes son 2. La primera es la clase ‘NullScope’ que es la misma implementación que tiene ‘NullLogger’. Esta clase es necesaria para la implementación de ‘BeginScope’ de nuestro propio ILogger. La segunda es que mi ‘SpyLogger’ recibe como parámetro el logger de xUnit y escribe sobre él. Con esto la salida de las pruebas registra todos los mensajes de log que registraría la aplicación y tengo una información muy valiosa sobre la ejecución de las pruebas.

Con esta clase ‘SpyLogger’ he conseguido hacer un mock sobre ILogger en .Net Core 3.x y relanzar los mensajes hacia la consola del runner de xUnit.

Aunque en este caso concreto la necesidad era relanzar las trazas de log hacia la consola de xUnit, esta puede ser la implementación base sobre la que añadir diferentes funcionalidades. Por ejemplo, si hacer verificaciones fuese necesario además de la funcionalidad que ya hay, se podría hacer el código necesario para las verificaciones o incluso recibir un ILogger en el constructor y cambiar el método Log para que llame de nuevo al ILogger. El cambio sería que ahora ese ILogger recibido como parámetro en el constructor si sería un mock normal de Moq sobre el que si podemos hacer verificaciones.

Aunque el código es un poco enrevesado y hay que añadir una capa extra de trabajo, es la mejor solución que he encontrado y quería compartirla por si a alguien le puede ayudar a afrontar el problema con el que me he encontrado yo.

Si por el contrario ya te ha tocado enfrentar este problema de hacer mock de ILogger en .Net Core 3 y crees que tu solución es mejor, no dudes en dejar un comentario planteándola.

En la próxima entrada hablaremos de un tema muy interesante como es el escribir código de alto rendimiento con .Net Core. ¡No te lo pierdas!