serilog-mssql / serilog-sinks-mssqlserver

A Serilog sink that writes events to Microsoft SQL Server and Azure SQL
Apache License 2.0
283 stars 148 forks source link

Console logging works but database logging does not work if Log.Logger is not assigned #586

Closed sam-wheat closed 1 month ago

sam-wheat commented 1 month ago

I spent all day chasing my tail wondering why logging to my db was not working. Turns out that if Log.Logger is not assigned, logging to the database does not work. IDK if this is by design or not. It is confusing that console logging works but not database logging, which led me to needlessly troubleshoot the database logging configuration.

This search leads me to believe I should not need to set Log.Logger.

The reason I create a logger object is because I inject Microsoft.Extenions.Logging.ILogger into a service library I use. The top level apps that depends on this library do not require logging to a database - only the library logs to the database. For this reason I did not want to assign to static Log.Logger - I want to inject a keyed instance of logger into my library so only it will log to the database.

services.AddLogging(loggingBuilder => loggingBuilder.AddSerilog(dispose: true));
// Create a configured Serilog logger
string loggingConnectionString = "...";
Serilog.ILogger serilogLogger = ConfigureLogger(loggingConnectionString).CreateLogger().ForContext("LoggerKey", "pipelineLogger");
// Convert the Serilog logger to a Microsoft ILogger
Microsoft.Extensions.Logging.ILogger msLogger = new SerilogLoggerFactory(serilogLogger).CreateLogger("pipelineLogger");
// Register the Microsoft Logger 
services.AddKeyedSingleton("pipelineLogger", msLogger);
ContainerBuilder builder = new AutofacServiceProviderFactory().CreateBuilder(services); // Merge Autofac and dotnet containers

// Register a factory for the ms logger
builder.Register<Func<string, Microsoft.Extensions.Logging.ILogger>>(c =>
{
    IComponentContext cxt = c.Resolve<IComponentContext>();
    return x => cxt.ResolveKeyed<Microsoft.Extensions.Logging.ILogger>(x);
});

I show the code above to demonstrate why I need a keyed logger object versus static Log.Logger. Perhaps I am overthinking it? In any case, here is a console app that replicates the problem with not assigning to Log.Logger:

using System.Collections.ObjectModel;
using System.Diagnostics;
using Serilog;
using Serilog.Events;
using Serilog.Sinks.MSSqlServer;

string connectionString = "Server=yada";
var columnOptions = new ColumnOptions();
columnOptions.Store.Remove(StandardColumn.Properties);
columnOptions.Store.Remove(StandardColumn.MessageTemplate);
columnOptions.Store.Remove(StandardColumn.Message);
columnOptions.Store.Remove(StandardColumn.Exception);
columnOptions.Store.Remove(StandardColumn.TimeStamp);
columnOptions.Store.Remove(StandardColumn.Level);
columnOptions.Store.Remove(StandardColumn.LogEvent);
columnOptions.Store.Remove(StandardColumn.SpanId);
columnOptions.Store.Remove(StandardColumn.Id);
columnOptions.Store.Remove(StandardColumn.TraceId);

columnOptions.AdditionalColumns = new Collection<SqlColumn>
        {
            new SqlColumn { ColumnName = "Pipeline", PropertyName = "Pipeline", DataType = System.Data.SqlDbType.NVarChar, DataLength=100, AllowNull=false },
            new SqlColumn { ColumnName = "PipelineRunID", PropertyName = "PipelineRunID", DataType = System.Data.SqlDbType.UniqueIdentifier, AllowNull = true },
            new SqlColumn { ColumnName = "ParentPipelineRunID", PropertyName = "ParentPipelineRunID", DataType = System.Data.SqlDbType.UniqueIdentifier, AllowNull = true },
            new SqlColumn { ColumnName = "Status", PropertyName = "Status", DataType = System.Data.SqlDbType.NVarChar, DataLength=50, AllowNull = true },
            new SqlColumn { ColumnName = "StatusDetails", PropertyName = "StatusDetails", DataType = System.Data.SqlDbType.NVarChar, DataLength=1000, AllowNull = true }
        };
LoggerConfiguration config = new();
config.WriteTo.Console();
config.WriteTo.MSSqlServer(
    connectionString: connectionString,
    restrictedToMinimumLevel: LogEventLevel.Debug,
    sinkOptions: new MSSqlServerSinkOptions
    {
        AutoCreateSqlDatabase = false,
        AutoCreateSqlTable = false,
        SchemaName = "dbo",
        TableName = "DataFactoryLog2",
        BatchPostingLimit = 1,
    },
    columnOptions: columnOptions);

ILogger logger = config.CreateLogger();

Serilog.Debugging.SelfLog.Enable(msg =>
{
    Debug.Print(msg);
    Debugger.Break();
});

logger.Information("{Pipeline}", "This will log to the db only if Log.Logger is assgined even though the log statement occurs before the assignment.");
//Log.Logger = logger;  // No database logging will occur if this line is commented.
logger.Information("{Pipeline}", "Logs to both console and database when Log.Logger is assigned.  Logs only to console when Log.Logger is not assigned.");
Log.Information("{Pipeline}","Logs to both console and database when Log.Logger is assigned.  Does not log to console or db when Log.Logger is not assigned.");
Log.CloseAndFlush();

Serilog versions

<ItemGroup>
    <PackageReference Include="Microsoft.Extensions.DependencyInjection.Abstractions" Version="8.0.2" />
    <PackageReference Include="Microsoft.Extensions.Logging" Version="8.0.1" />
    <PackageReference Include="Microsoft.Extensions.Configuration.Json" Version="8.0.1" />  
    <PackageReference Include="Serilog.Extensions.Hosting" Version="8.0.0" />  
    <PackageReference Include="Serilog.Extensions.Logging" Version="8.0.0" />
    <PackageReference Include="Serilog.AspNetCore" Version="8.0.3" />
    <PackageReference Include="Serilog.Sinks.MSSqlServer" Version="7.0.1" />
</ItemGroup>

OS is Windows, Target framework is net 8.

cancakar35 commented 1 month ago

In my opinion, your logs not flushing before application exit. If you don't want to use static Log class you should call the dispose method for your logger.

sam-wheat commented 1 month ago

@cancakar35 your opinion is spot on. Makes sense that Log.CloseAndFulsh() is not going to work.

Thanks.