Serilog MSSqlServer is not logging errors

Question

Before I get into the problem, I must explain where and why I created the code the way I did. I am following a tutorial on PluralSight which explains logging:

https://app.pluralsight.com/library/courses/dotnet-logging-using-serilog-opinionated-approach/discussion

So, I created a static class and amended it slightly (because the course is out of date) and came up with this:

public static class Logger
{
    private static ILogger _diagnosticLogger;
    private static ILogger _errorLogger;
    private static ILogger _performanceLogger;
    private static ILogger _usageLogger;

    public static void AddLogging(this IServiceCollection services, IConfiguration configuration, string sectionName = "Logging")
    {
        services.Configure<LoggerConfig>(configuration.GetSection(sectionName));
        services.AddSingleton(m => m.GetRequiredService<IOptions<LoggerConfig>>().Value);

        var scope = services.BuildServiceProvider().CreateScope();
        var config = scope.ServiceProvider.GetRequiredService<LoggerConfig>();

        _diagnosticLogger = CreateLogger("DiagnosticLogs", config.ConnectionString);
        _errorLogger = CreateLogger("ErrorLogs", config.ConnectionString);
        _performanceLogger = CreateLogger("PerformanceLogs", config.ConnectionString);
        _usageLogger = CreateLogger("UsageLogs", config.ConnectionString);
    }

    public static void LogDiagnostic(Log log)
    {
        var shouldWrite = Convert.ToBoolean(Environment.GetEnvironmentVariable("LOG_DIAGNOSTICS"));
        if (!shouldWrite) return;

        _diagnosticLogger.Write(LogEventLevel.Information, "{@Log}", log);
    }

    public static void LogError(Log log)
    {
        log.Message = GetMessageFromException(log.Exception);
        _errorLogger.Write(LogEventLevel.Information, "{@Log}", log);
    }

    public static void LogPerformance(Log log) =>
        _performanceLogger.Write(LogEventLevel.Information, "{@Log}", log);

    public static void LogUsage(Log log) =>
        _usageLogger.Write(LogEventLevel.Information, "{@Log}", log);

    private static string GetMessageFromException(Exception exception)
    {
        while (true)
        {
            if (exception.InnerException == null) return exception.Message;
            exception = exception.InnerException;
        }
    }

    private static ILogger CreateLogger(string name, string connectionString) =>
        new LoggerConfiguration()
            //.WriteTo.File(path: Environment.GetEnvironmentVariable(name))
            .WriteTo.MSSqlServer(connectionString, 
                sinkOptions: GetSinkOptions(name),
                columnOptions: GetColumnOptions())
            .CreateLogger();

    private static ColumnOptions GetColumnOptions()
    {
        var columnOptions = new ColumnOptions();

        columnOptions.Store.Remove(StandardColumn.Exception);
        columnOptions.Store.Remove(StandardColumn.Level);
        columnOptions.Store.Remove(StandardColumn.Message);
        columnOptions.Store.Remove(StandardColumn.MessageTemplate);
        columnOptions.Store.Remove(StandardColumn.Properties);
        columnOptions.Store.Remove(StandardColumn.TimeStamp);

        columnOptions.AdditionalColumns = new Collection<SqlColumn>
        {
            new SqlColumn { DataType = SqlDbType.VarChar, ColumnName = "AdditionalInformation"},
            new SqlColumn { DataType = SqlDbType.VarChar, ColumnName = "CorrelationId"},
            new SqlColumn { DataType = SqlDbType.VarChar, ColumnName = "CustomException"},
            new SqlColumn { DataType = SqlDbType.Int, ColumnName = "ElapsedMilliseconds"},
            new SqlColumn { DataType = SqlDbType.VarChar, ColumnName = "Exception"},
            new SqlColumn { DataType = SqlDbType.VarChar, ColumnName = "Hostname"},
            new SqlColumn { DataType = SqlDbType.VarChar, ColumnName = "Layer"},
            new SqlColumn { DataType = SqlDbType.VarChar, ColumnName = "Location"},
            new SqlColumn { DataType = SqlDbType.VarChar, ColumnName = "Message"},
            new SqlColumn { DataType = SqlDbType.VarChar, ColumnName = "Model"},
            new SqlColumn { DataType = SqlDbType.DateTime, ColumnName = "Timestamp"},
            new SqlColumn { DataType = SqlDbType.VarChar, ColumnName = "UserId"},
            new SqlColumn { DataType = SqlDbType.VarChar, ColumnName = "UserEmail"}
        };

        return columnOptions;
    }

    private static SinkOptions GetSinkOptions(string name)
    {
        return new SinkOptions
        {
            TableName = name,
            AutoCreateSqlTable = true,
            BatchPostingLimit = 1
        };
    }
}

In my Startup.cs I have initialized the Loggers by calling the AddLogging method like this:

services.AddLogging(Configuration, nameof(DataConfig));

which executes this method:

public static void AddLogging(this IServiceCollection services, IConfiguration configuration, string sectionName = "Logging")
{
    services.Configure<LoggerConfig>(configuration.GetSection(sectionName));
    services.AddSingleton(m => m.GetRequiredService<IOptions<LoggerConfig>>().Value);

    var scope = services.BuildServiceProvider().CreateScope();
    var config = scope.ServiceProvider.GetRequiredService<LoggerConfig>();

    _diagnosticLogger = CreateLogger("DiagnosticLogs", config.ConnectionString);
    _errorLogger = CreateLogger("ErrorLogs", config.ConnectionString);
    _performanceLogger = CreateLogger("PerformanceLogs", config.ConnectionString);
    _usageLogger = CreateLogger("UsageLogs", config.ConnectionString);
}

private static ILogger CreateLogger(string name, string connectionString) =>
    new LoggerConfiguration()
        //.WriteTo.File(path: Environment.GetEnvironmentVariable(name))
        .WriteTo.MSSqlServer(connectionString, 
            sinkOptions: GetSinkOptions(name),
            columnOptions: GetColumnOptions())
        .CreateLogger();

As you can see, the loggers should be created fine. Then I have added a custom middleware:

public class ErrorHandlerMiddleware
{
    private readonly RequestDelegate _next;

    public ErrorHandlerMiddleware(RequestDelegate next)
    {
        _next = next;
    }

    public async Task InvokeAsync(HttpContext httpContext)
    {
        try
        {
            await _next(httpContext);
        }
        catch (Exception ex)
        {
            await HandleExceptionAsync(httpContext, ex);
        }
    }

    private static async Task HandleExceptionAsync(HttpContext context, Exception exception)
    {
        context.Response.ContentType = "application/json";
        context.Response.StatusCode = (int)HttpStatusCode.InternalServerError;

        switch (exception)
        {
            case NotFoundException _:
                context.Response.StatusCode = (int)HttpStatusCode.NotFound;
                break;
            case BadRequestException _:
                context.Response.StatusCode = (int)HttpStatusCode.BadRequest;
                break;
        }

        WebHelper.LogWebError(null, "Core API", exception, context);

        var errorId = Activity.Current?.Id ?? context.TraceIdentifier;
        var response = JsonConvert.SerializeObject(new ErrorResponse
        {
            ErrorId = errorId,
            Message = "An error occurred in the API."
        });
        await context.Response.WriteAsync(response, Encoding.UTF8);
    }
}

Which I have an extension method for adding to my project:

public static class ErrorHandlerMiddlewareExtensions
{
    public static IApplicationBuilder UseErrorHandling(this IApplicationBuilder builder)
        => builder.UseMiddleware<ErrorHandlerMiddleware>();
}

When I use postman to call a method to get an error, I get a nicely formatted error like this:

{
    "ErrorId": "|e55d889c-463ad56fc704d7fb.",
    "Message": "An error occurred in the API."
}

I have put breakpoints in my code stepped through it all, the log says it has been created (by invoking the LogError method) and it all seems to be fine.

If I check my database though; I can see the tables have been created, but there are no records.

I added a try/catch block to my LogError method like this:

public static void LogError(Log log)
{
    try
    {

        log.Message = GetMessageFromException(log.Exception);
        _errorLogger.Write(LogEventLevel.Information, "{@Log}", log);
    }
    catch (Exception ex)
    {

    }
}

And no error is thrown, it all executes as it should but no record is added in my database. Does anyone know why?

UPDATE

I have noticed after playing around a bit that it is actually trying to record the data, it's just that all the columns are null.

If I removed my column options, it does actually add the log to the database. So it's something to do with mapping. Can anyone help me with that?

This is what my log looks like:

public class Log
{
    public DateTime TimeStamp { get; }
    public string Message { get; set; }

    public string Model { get; set; }
    public string Layer { get; set; }
    public string Location { get; set; }
    public string HostName { get; set; }
    public string UserId { get; set; }
    public string UserEmail { get; set; }
    public long? ElapsedMilliseconds { get; set; }
    public string CorrelationId { get; set; }
    public Exception Exception { get; set; }
    public Dictionary<string, string> AdditionalInformation { get; set; }

    public Log() => TimeStamp = DateTime.UtcNow;
}

And as you can see, I am trying to log it to this:

private static ColumnOptions GetColumnOptions()
{
    var columnOptions = new ColumnOptions();

    columnOptions.Store.Remove(StandardColumn.Exception);
    columnOptions.Store.Remove(StandardColumn.Level);
    columnOptions.Store.Remove(StandardColumn.Message);
    columnOptions.Store.Remove(StandardColumn.MessageTemplate);
    columnOptions.Store.Remove(StandardColumn.Properties);
    columnOptions.Store.Remove(StandardColumn.TimeStamp);

    columnOptions.AdditionalColumns = new Collection<SqlColumn>
    {
        new SqlColumn { DataType = SqlDbType.VarChar, ColumnName = "AdditionalInformation"},
        new SqlColumn { DataType = SqlDbType.VarChar, ColumnName = "CorrelationId"},
        new SqlColumn { DataType = SqlDbType.VarChar, ColumnName = "CustomException"},
        new SqlColumn { DataType = SqlDbType.Int, ColumnName = "ElapsedMilliseconds", AllowNull = true},
        new SqlColumn { DataType = SqlDbType.VarChar, ColumnName = "Exception"},
        new SqlColumn { DataType = SqlDbType.VarChar, ColumnName = "Hostname"},
        new SqlColumn { DataType = SqlDbType.VarChar, ColumnName = "Layer"},
        new SqlColumn { DataType = SqlDbType.VarChar, ColumnName = "Location"},
        new SqlColumn { DataType = SqlDbType.VarChar, ColumnName = "Message"},
        new SqlColumn { DataType = SqlDbType.VarChar, ColumnName = "Model"},
        new SqlColumn { DataType = SqlDbType.DateTime, ColumnName = "Timestamp"},
        new SqlColumn { DataType = SqlDbType.VarChar, ColumnName = "UserId"},
        new SqlColumn { DataType = SqlDbType.VarChar, ColumnName = "UserEmail"}
    };

    return columnOptions;
}

Did you try enabling self logging as the documentation suggests? Did you try removing the empty catch blocks? Why do you have the clunky code to grab inner exceptions, when you could just log the entire exception? — mason
– mason, Commented Jun 11, 2020 at 17:02
Your static class duplicates Serilog's own classes and methods and tries to do what the AddSerilog and UseSerilog methods from Serilog.Extensions.Logging do. Why not use the ready-made middleware? — Panagiotis Kanavos
– Panagiotis Kanavos, Commented Jun 12, 2020 at 10:42
Can you provide a link to this? As I mentioned before; I was following a tutorial on pluralsight. If there is a better way, I will use it :) — r3plica
– r3plica, Commented Jun 16, 2020 at 13:26

r3plica · Accepted Answer · 2020-06-12 10:36:24Z

I managed to get this working. I am not sure why I can't find any documentation for it anywhere, but this is what I did. The first thing I did was modify my column options to this:

private static ColumnOptions GetColumnOptions()
{
    var columnOptions = new ColumnOptions();

    columnOptions.Store.Remove(StandardColumn.Level);
    columnOptions.Store.Remove(StandardColumn.Message);
    columnOptions.Store.Remove(StandardColumn.MessageTemplate);
    columnOptions.Store.Remove(StandardColumn.Properties);

    columnOptions.AdditionalColumns = new Collection<SqlColumn>
    {
        new SqlColumn { DataType = SqlDbType.VarChar, ColumnName = "AdditionalInformation"},
        new SqlColumn { DataType = SqlDbType.VarChar, ColumnName = "CorrelationId"},
        new SqlColumn { DataType = SqlDbType.Int, ColumnName = "ElapsedMilliseconds", AllowNull = true},
        new SqlColumn { DataType = SqlDbType.VarChar, ColumnName = "Hostname"},
        new SqlColumn { DataType = SqlDbType.VarChar, ColumnName = "Layer"},
        new SqlColumn { DataType = SqlDbType.VarChar, ColumnName = "Location"},
        new SqlColumn { DataType = SqlDbType.VarChar, ColumnName = "Message"},
        new SqlColumn { DataType = SqlDbType.VarChar, ColumnName = "Model"},
        new SqlColumn { DataType = SqlDbType.VarChar, ColumnName = "UserId"},
        new SqlColumn { DataType = SqlDbType.VarChar, ColumnName = "UserEmail"}
    };

    return columnOptions;
}

I intend to set the DataLength later, but as you can see I removed some columns in not interested in and then add my own.

I then modified the way I was writing the log to this:

public static void LogError(Log log)
{
    log.Message = GetMessageFromException(log.Exception);
    _errorLogger.PopulateCustomColumns(log).Write(LogEventLevel.Information, log.Exception, "{@Log}", log);
}

Two things have changed here, first I have added the Exception to the invocation and second, I have added a new method called PopulateCustomColumns which looks like this:

private static ILogger PopulateCustomColumns(this ILogger logger, Log log)
{
    var additionalInformation = JsonConvert.SerializeObject(log.AdditionalInformation);
    return logger
        .ForContext("AdditionalInformation", additionalInformation)
        .ForContext("CorrelationId", log.CorrelationId)
        .ForContext("ElapsedMilliseconds", log.ElapsedMilliseconds)
        .ForContext("Hostname", log.HostName)
        .ForContext("Layer", log.Layer)
        .ForContext("Location", log.Location)
        .ForContext("Message", log.Message)
        .ForContext("Model", log.Model)
        .ForContext("UserId", log.UserId)
        .ForContext("UserEmail", log.UserEmail);
}

It's worth noting that without adding the messageTemplate it doesn't log anything (Except the timestamp). I hope this helps someone else.

For completion, here is the entire Logger class:

public static class Logger
{
    private static ILogger _diagnosticLogger;
    private static ILogger _errorLogger;
    private static ILogger _performanceLogger;
    private static ILogger _usageLogger;

    public static void AddLogging(this IServiceCollection services, IConfiguration configuration, string sectionName = "Logging")
    {
        services.Configure<LoggerConfig>(configuration.GetSection(sectionName));
        services.AddSingleton(m => m.GetRequiredService<IOptions<LoggerConfig>>().Value);

        var scope = services.BuildServiceProvider().CreateScope();
        var config = scope.ServiceProvider.GetRequiredService<LoggerConfig>();

        var t = Path.Combine(Directory.GetCurrentDirectory(), "self.log");
        var file = File.CreateText(Path.Combine(Directory.GetCurrentDirectory(), "self.log"));

        Serilog.Debugging.SelfLog.Enable(TextWriter.Synchronized(file));

        _diagnosticLogger = CreateLogger("DiagnosticLogs", config.ConnectionString);
        _errorLogger = CreateLogger("ErrorLogs", config.ConnectionString);
        _performanceLogger = CreateLogger("PerformanceLogs", config.ConnectionString);
        _usageLogger = CreateLogger("UsageLogs", config.ConnectionString);
    }

    public static void LogDiagnostic(Log log)
    {
        var shouldWrite = Convert.ToBoolean(Environment.GetEnvironmentVariable("LOG_DIAGNOSTICS"));
        if (!shouldWrite) return;

        _diagnosticLogger.PopulateCustomColumns(log).Write(LogEventLevel.Information, log.Exception, "{@Log}", log);
    }

    public static void LogError(Log log)
    {
        log.Message = GetMessageFromException(log.Exception);
        _errorLogger.PopulateCustomColumns(log).Write(LogEventLevel.Information, log.Exception, "{@Log}", log);
    }

    public static void LogPerformance(Log log) =>
        _performanceLogger.PopulateCustomColumns(log).Write(LogEventLevel.Information, log.Exception, "{@Log}", log);

    public static void LogUsage(Log log) =>
        _usageLogger.PopulateCustomColumns(log).Write(LogEventLevel.Information, log.Exception, "{@Log}", log);

    private static string GetMessageFromException(Exception exception)
    {
        while (true)
        {
            if (exception.InnerException == null) return exception.Message;
            exception = exception.InnerException;
        }
    }

    private static ILogger CreateLogger(string name, string connectionString) =>
        new LoggerConfiguration()
            //.WriteTo.File(path: Environment.GetEnvironmentVariable(name))
            .WriteTo.MSSqlServer(connectionString, 
                sinkOptions: GetSinkOptions(name),
                columnOptions: GetColumnOptions())
            .CreateLogger();

    private static ColumnOptions GetColumnOptions()
    {
        var columnOptions = new ColumnOptions();

        columnOptions.Store.Remove(StandardColumn.Level);
        columnOptions.Store.Remove(StandardColumn.Message);
        columnOptions.Store.Remove(StandardColumn.MessageTemplate);
        columnOptions.Store.Remove(StandardColumn.Properties);

        columnOptions.AdditionalColumns = new Collection<SqlColumn>
        {
            new SqlColumn { DataType = SqlDbType.VarChar, ColumnName = "AdditionalInformation"},
            new SqlColumn { DataType = SqlDbType.VarChar, ColumnName = "CorrelationId"},
            new SqlColumn { DataType = SqlDbType.Int, ColumnName = "ElapsedMilliseconds", AllowNull = true},
            new SqlColumn { DataType = SqlDbType.VarChar, ColumnName = "Hostname"},
            new SqlColumn { DataType = SqlDbType.VarChar, ColumnName = "Layer"},
            new SqlColumn { DataType = SqlDbType.VarChar, ColumnName = "Location"},
            new SqlColumn { DataType = SqlDbType.VarChar, ColumnName = "Message"},
            new SqlColumn { DataType = SqlDbType.VarChar, ColumnName = "Model"},
            new SqlColumn { DataType = SqlDbType.VarChar, ColumnName = "UserId"},
            new SqlColumn { DataType = SqlDbType.VarChar, ColumnName = "UserEmail"}
        };

        return columnOptions;
    }

    private static ILogger PopulateCustomColumns(this ILogger logger, Log log)
    {
        var additionalInformation = JsonConvert.SerializeObject(log.AdditionalInformation);
        return logger
            .ForContext("AdditionalInformation", additionalInformation)
            .ForContext("CorrelationId", log.CorrelationId)
            .ForContext("ElapsedMilliseconds", log.ElapsedMilliseconds)
            .ForContext("Hostname", log.HostName)
            .ForContext("Layer", log.Layer)
            .ForContext("Location", log.Location)
            .ForContext("Message", log.Message)
            .ForContext("Model", log.Model)
            .ForContext("UserId", log.UserId)
            .ForContext("UserEmail", log.UserEmail);
    }

    private static SinkOptions GetSinkOptions(string name)
    {
        return new SinkOptions
        {
            TableName = name,
            AutoCreateSqlTable = true,
            BatchPostingLimit = 1
        };
    }
}

Serilog already provides the Serilog.Extensions.Logging middleware for integration with System.Extensions.Logging. You'll find docs for Serilog's database sink, the integration middleware but not how to create your own integration middleware.
Can you give me an example of how to use it and how it replaces my middleware?

Collectives™ on Stack Overflow

Serilog MSSqlServer is not logging errors

1 Answer 1

2 Comments

Your Answer

Hot Network Questions

Collectives™ on Stack Overflow

1 Answer 1

2 Comments

Your Answer

Sign up or log in

Post as a guest

Related