C
C#•2mo ago
Foxtrek_64

Custom Logger

Hi all, been trying to figure this out for a bit now but I'm not sure what's happening. I am writing a custom extension for Microsoft.Extensions.Logging to write to a Sql Server database with a particular schema. However, I'd opted to make it as generic as possible. After doing a lot of research, I've created a DbLoggingProvider and a MSSqlDatabaseLogger. The logging provider creates new instances of the database logger, as expected, and the database logger expects an instance of a type implementing ILogAgent which it forwards its log method to. The log agent is responsible for performing the database-specific operations. However, when doing unit tests, I am unable to prove that logging works. In fact, it appears to not. Take the following test. 
[Fact]
public void LogsToDatabase()
{
    using var accessor = new SqlServerAccesor(_connectionString); // SqlServerAccessor wraps a SqlConnection and exposes helpers to run queries and non-queries.

    int? oldCount = GetCount(accessor); // Uses the accessor to run a query to check count of rows in a table.
    Assert.NotNull(oldCount);

    var logger = _host.Services.GetService<ILogger<LoggerTests>>();
    Assert.NotNull(logger);

    var exception = Record.Exception(() => logger.LogInformation("..."));
    Assert.Null(exception);

    int? newCount = GetCount(accessor);
    Assert.NotNull(newCount);
    Assert.NotEqual(oldCount, newCount);
}
[Fact]
public void LogsToDatabase()
{
    using var accessor = new SqlServerAccesor(_connectionString); // SqlServerAccessor wraps a SqlConnection and exposes helpers to run queries and non-queries.

    int? oldCount = GetCount(accessor); // Uses the accessor to run a query to check count of rows in a table.
    Assert.NotNull(oldCount);

    var logger = _host.Services.GetService<ILogger<LoggerTests>>();
    Assert.NotNull(logger);

    var exception = Record.Exception(() => logger.LogInformation("..."));
    Assert.Null(exception);

    int? newCount = GetCount(accessor);
    Assert.NotNull(newCount);
    Assert.NotEqual(oldCount, newCount);
}
I'm sure that there are better ways to test if a logger is logging (this could in theory pass if something else is writing logs to this table even if the log operation fails), but it's fine for right now while I'm the only person logging to this table. That said, advice on fixing up this test would be appreciated. Every assert passes except for the assertion that the counts are not equal (they are) and going to the database reveals that my message was not inserted into the log table. I have unit tests that pass for SqlServerAccessor and I am able to demonstrate that, by itself, it is able to insert log entries by executing a non-query and writing directly to the table in question. The issue appears to be in the glue layer - despite the log agent being present in the same service provider which is producing logger instances, it does not appear to be using my particular logger. I don't see any breakpoints being hit in my logger class, though I am hitting the logger provider several times. What is it exactly that I am missing here?
7 Replies
Sossenbinder
Sossenbinder•2mo ago
Since a DB is involved, any chance there is an async operation involved for writing out the logs or flushing any buffers? Since the test steps through synchronously, is the DB access being done synchronously, or could this be a race condition?
mtreit
mtreit•2mo ago
I would probably try setting up a logger that supports multiple sinks (The DB sink and a test sync that just does Console.WriteLine or whatever) and make sure the test sink is getting called in the test, to start with.
Foxtrek_64
Foxtrek_64OP•2mo ago
Not sure how to see the output from that console logger in an xunit process
mtreit
mtreit•2mo ago
If you run in Visual Studio it captures stdout of the test if you click on the test. You could also write to a file or whatever. Just something to validate it's getting called.
Foxtrek_64
Foxtrek_64OP•2mo ago
Everything is synchronous in my db access library. There could be some asynchronicity with regards to the application host though.
mtreit
mtreit•2mo ago
You said you set a breakpoint and the logger is never called at all, that would indicate some other issue. Not a sync / async issue. At least, doesn't sound like it.
Foxtrek_64
Foxtrek_64OP•2mo ago
I do see a lot of calls to my logger provider's CreateLogger() function 
public ILogger CreateLogger(string categoryName)
    => _loggers.GetOrAdd(categoryName, name => new MSSqlDatabaseLogger(name, _currentConfig, _logAgent, _scopeProvider));
public ILogger CreateLogger(string categoryName)
    => _loggers.GetOrAdd(categoryName, name => new MSSqlDatabaseLogger(name, _currentConfig, _logAgent, _scopeProvider));
_loggers is a concurrent dictionary (made it that in case of this being issues with async, but it can probaby be a regular dictionary) of string, MSSqlDatabaseLogger. The current options are provided by IOptionsMonitor<> And the scope provider is an IExternalScopeProvider instance, which defaults to a no-op scope shamelessly copied from the M.E.L.Console no-scope provider. But I'm not hitting any breakpoints inside of the logger nor the log agent. This is the important part of the body of the database logger. I'm not hitting the if check to see if the logger is enabled though. 
public bool IsEnabled(LogLevel logLevel)
{
    return options.LevelSwitch is not LogLevel.None && logLevel >= options.LevelSwitch;
}

public void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Exception? exception, Func<TState, Exception?, string> formatter)
{
    if (IsEnabled(logLevel))
    {
        logAgent.WriteToDatabase(logLevel, eventId, state, exception, formatter);
    }
}
public bool IsEnabled(LogLevel logLevel)
{
    return options.LevelSwitch is not LogLevel.None && logLevel >= options.LevelSwitch;
}

public void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Exception? exception, Func<TState, Exception?, string> formatter)
{
    if (IsEnabled(logLevel))
    {
        logAgent.WriteToDatabase(logLevel, eventId, state, exception, formatter);
    }
}
I was able to figure it out. My SqlServer library was named Microsoft.Extensions.Logging.SqlServer and the tests library adds the .Tests node to the namespace. It was correctly pulling in appsettings data that told it that 
{
  "Logging:LogLevel:Microsoft": "Warning"
}
{
  "Logging:LogLevel:Microsoft": "Warning"
}
So naturally an information message was being excluded. I created a new type with a new namespace in my test library to simulate a consumer and now everything is happy

Did you find this page helpful?