I'm trying to use Serilog to write an audit log for a subset of log events.
That is, of all the events which are logged, a subset should be logged using a sub-logger to my chosen sink(s) and if it fails, I want it to fail noisily with an exception.
My Serilog logger configuration is as follows:
var logger = new LoggerConfiguration()
.MinimumLevel.Debug()
.AuditTo.Logger(l =>
{
// Customising the SQL Server sink
// The as-yet-not-created table will match these customisations.
var sqlSinkOpts = new MSSqlServerSinkOptions
{
TableName = "LogTable",
AutoCreateSqlTable = false
};
var sqlSinkColOpts = new ColumnOptions
{
AdditionalColumns = new Collection<SqlColumn> {
new SqlColumn { ColumnName = "Something", DataType = SqlDbType.UniqueIdentifier },
new SqlColumn { ColumnName = "SomethingElse", DataType = SqlDbType.NVarChar }
}
};
sqlSinkColOpts.Level.StoreAsEnum = true;
sqlSinkColOpts.Store.Remove(StandardColumn.MessageTemplate);
sqlSinkColOpts.Store.Remove(StandardColumn.Properties);
// Configure the logger
l.Filter.ByIncludingOnly(Matching.FromSource("Namespace.We.Care.About"))
.AuditTo.MSSqlServer(connectionString: ConfigurationManager.ConnectionStrings["Database"].ConnectionString,
sinkOptions: sqlSinkOpts,
columnOptions: sqlSinkColOpts);
})
.CreateLogger();
The intention here is that I'm logging only log events generated from within Namespace.We.Care.About to LogTable in the database using the MS SQL Server sink. If it fails, it ought to fail loudly; we need the logs for this.
At the moment, I'm testing this by having not yet created the log table in the database. Therefore I would expect this to fail.
I'm not sure if my configuration is incorrect - the fact that it allows audit logging using a sub-logger in the first place implies this kind of configuration is valid and supported - or if I have a different problem somewhere.
My current assumption is that either audit logging using a sub-logger just doesn't work (as I expect), or I'm doing something wrong with my configuration.
Another point of potential relevance: I'm also using Serilog.Extensions.Logging to allow use of Microsoft.Extensions.Logging. The log events in question are generated that way (that is, code within Namespace.We.Care.About is using instances of Microsoft.Extensions.Logging.ILogger<Whatever> to generate its log events and has has no idea Serilog exists). I'm not expecting this to have any impact but thought I'd throw this fact in just in case.
Edit
I've checked Serilog's SelfLog and the exceptions writing the log events are occurring as expected. They're just not propagating back out into the application as I would have expected in the audit logging scenario.
2022-10-25T10:26:18.1939244Z Failed to write event through SerilogLogger: System.AggregateException: Failed to emit a log event. ---> System.AggregateException: Failed to emit a log event. ---> Microsoft.Data.SqlClient.SqlException: Invalid object name 'dbo.LogTable'.
at Microsoft.Data.SqlClient.SqlConnection.OnError(SqlException exception, Boolean breakConnection, Action`1 wrapCloseInAction) in D:\a\_work\1\s\src\Microsoft.Data.SqlClient\netfx\src\Microsoft\Data\SqlClient\SqlConnection.cs:line 2363
at Microsoft.Data.SqlClient.TdsParser.ThrowExceptionAndWarning(TdsParserStateObject stateObj, Boolean callerHasConnectionLock, Boolean asyncClose) in D:\a\_work\1\s\src\Microsoft.Data.SqlClient\netfx\src\Microsoft\Data\SqlClient\TdsParser.cs:line 1775
at Microsoft.Data.SqlClient.TdsParser.TryRun(RunBehavior runBehavior, SqlCommand cmdHandler, SqlDataReader dataStream, BulkCopySimpleResultSet bulkCopyHandler, TdsParserStateObject stateObj, Boolean& dataReady) in D:\a\_work\1\s\src\Microsoft.Data.SqlClient\netfx\src\Microsoft\Data\SqlClient\TdsParser.cs:line 0
at Microsoft.Data.SqlClient.SqlCommand.FinishExecuteReader(SqlDataReader ds, RunBehavior runBehavior, String resetOptionsString, Boolean isInternal, Boolean forDescribeParameterEncryption, Boolean shouldCacheForAlwaysEncrypted) in D:\a\_work\1\s\src\Microsoft.Data.SqlClient\netfx\src\Microsoft\Data\SqlClient\SqlCommand.cs:line 5718
at Microsoft.Data.SqlClient.SqlCommand.RunExecuteReaderTds(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, Boolean async, Int32 timeout, Task& task, Boolean asyncWrite, Boolean inRetry, SqlDataReader ds, Boolean describeParameterEncryptionRequest) in D:\a\_work\1\s\src\Microsoft.Data.SqlClient\netfx\src\Microsoft\Data\SqlClient\SqlCommand.cs:line 5544
at Microsoft.Data.SqlClient.SqlCommand.RunExecuteReader(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, String method, TaskCompletionSource`1 completion, Int32 timeout, Task& task, Boolean& usedCache, Boolean asyncWrite, Boolean inRetry) in D:\a\_work\1\s\src\Microsoft.Data.SqlClient\netfx\src\Microsoft\Data\SqlClient\SqlCommand.cs:line 5148
at Microsoft.Data.SqlClient.SqlCommand.InternalExecuteNonQuery(TaskCompletionSource`1 completion, String methodName, Boolean sendToPipe, Int32 timeout, Boolean& usedCache, Boolean asyncWrite, Boolean inRetry) in D:\a\_work\1\s\src\Microsoft.Data.SqlClient\netfx\src\Microsoft\Data\SqlClient\SqlCommand.cs:line 2032
at Microsoft.Data.SqlClient.SqlCommand.ExecuteNonQuery() in D:\a\_work\1\s\src\Microsoft.Data.SqlClient\netfx\src\Microsoft\Data\SqlClient\SqlCommand.cs:line 1475
at Serilog.Sinks.MSSqlServer.Platform.SqlLogEventWriter.WriteEvent(LogEvent logEvent)
at Serilog.Core.Sinks.AggregateSink.Emit(LogEvent logEvent)
--- End of inner exception stack trace ---
at Serilog.Core.Sinks.AggregateSink.Emit(LogEvent logEvent)
at Serilog.Core.Sinks.FilteringSink.Emit(LogEvent logEvent)
at Serilog.Core.Sinks.AggregateSink.Emit(LogEvent logEvent)
--- End of inner exception stack trace ---
at Serilog.Core.Sinks.AggregateSink.Emit(LogEvent logEvent)
at Serilog.Extensions.Logging.SerilogLogger.Write[TState](LogEventLevel level, EventId eventId, TState state, Exception exception, Func`3 formatter)
at Serilog.Extensions.Logging.SerilogLogger.Log[TState](LogLevel logLevel, EventId eventId, TState state, Exception exception, Func`3 formatter)
---> (Inner Exception #0) System.AggregateException: Failed to emit a log event. ---> Microsoft.Data.SqlClient.SqlException: Invalid object name 'dbo.LogTable'.
at Microsoft.Data.SqlClient.SqlConnection.OnError(SqlException exception, Boolean breakConnection, Action`1 wrapCloseInAction) in D:\a\_work\1\s\src\Microsoft.Data.SqlClient\netfx\src\Microsoft\Data\SqlClient\SqlConnection.cs:line 2363
at Microsoft.Data.SqlClient.TdsParser.ThrowExceptionAndWarning(TdsParserStateObject stateObj, Boolean callerHasConnectionLock, Boolean asyncClose) in D:\a\_work\1\s\src\Microsoft.Data.SqlClient\netfx\src\Microsoft\Data\SqlClient\TdsParser.cs:line 1775
at Microsoft.Data.SqlClient.TdsParser.TryRun(RunBehavior runBehavior, SqlCommand cmdHandler, SqlDataReader dataStream, BulkCopySimpleResultSet bulkCopyHandler, TdsParserStateObject stateObj, Boolean& dataReady) in D:\a\_work\1\s\src\Microsoft.Data.SqlClient\netfx\src\Microsoft\Data\SqlClient\TdsParser.cs:line 0
at Microsoft.Data.SqlClient.SqlCommand.FinishExecuteReader(SqlDataReader ds, RunBehavior runBehavior, String resetOptionsString, Boolean isInternal, Boolean forDescribeParameterEncryption, Boolean shouldCacheForAlwaysEncrypted) in D:\a\_work\1\s\src\Microsoft.Data.SqlClient\netfx\src\Microsoft\Data\SqlClient\SqlCommand.cs:line 5718
at Microsoft.Data.SqlClient.SqlCommand.RunExecuteReaderTds(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, Boolean async, Int32 timeout, Task& task, Boolean asyncWrite, Boolean inRetry, SqlDataReader ds, Boolean describeParameterEncryptionRequest) in D:\a\_work\1\s\src\Microsoft.Data.SqlClient\netfx\src\Microsoft\Data\SqlClient\SqlCommand.cs:line 5544
at Microsoft.Data.SqlClient.SqlCommand.RunExecuteReader(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, String method, TaskCompletionSource`1 completion, Int32 timeout, Task& task, Boolean& usedCache, Boolean asyncWrite, Boolean inRetry) in D:\a\_work\1\s\src\Microsoft.Data.SqlClient\netfx\src\Microsoft\Data\SqlClient\SqlCommand.cs:line 5148
at Microsoft.Data.SqlClient.SqlCommand.InternalExecuteNonQuery(TaskCompletionSource`1 completion, String methodName, Boolean sendToPipe, Int32 timeout, Boolean& usedCache, Boolean asyncWrite, Boolean inRetry) in D:\a\_work\1\s\src\Microsoft.Data.SqlClient\netfx\src\Microsoft\Data\SqlClient\SqlCommand.cs:line 2032
at Microsoft.Data.SqlClient.SqlCommand.ExecuteNonQuery() in D:\a\_work\1\s\src\Microsoft.Data.SqlClient\netfx\src\Microsoft\Data\SqlClient\SqlCommand.cs:line 1475
at Serilog.Sinks.MSSqlServer.Platform.SqlLogEventWriter.WriteEvent(LogEvent logEvent)
at Serilog.Core.Sinks.AggregateSink.Emit(LogEvent logEvent)
--- End of inner exception stack trace ---
at Serilog.Core.Sinks.AggregateSink.Emit(LogEvent logEvent)
at Serilog.Core.Sinks.FilteringSink.Emit(LogEvent logEvent)
at Serilog.Core.Sinks.AggregateSink.Emit(LogEvent logEvent)
---> (Inner Exception #0) Microsoft.Data.SqlClient.SqlException (0x80131904): Invalid object name 'dbo.LogTable'.
at Microsoft.Data.SqlClient.SqlConnection.OnError(SqlException exception, Boolean breakConnection, Action`1 wrapCloseInAction) in D:\a\_work\1\s\src\Microsoft.Data.SqlClient\netfx\src\Microsoft\Data\SqlClient\SqlConnection.cs:line 2363
at Microsoft.Data.SqlClient.TdsParser.ThrowExceptionAndWarning(TdsParserStateObject stateObj, Boolean callerHasConnectionLock, Boolean asyncClose) in D:\a\_work\1\s\src\Microsoft.Data.SqlClient\netfx\src\Microsoft\Data\SqlClient\TdsParser.cs:line 1775
at Microsoft.Data.SqlClient.TdsParser.TryRun(RunBehavior runBehavior, SqlCommand cmdHandler, SqlDataReader dataStream, BulkCopySimpleResultSet bulkCopyHandler, TdsParserStateObject stateObj, Boolean& dataReady) in D:\a\_work\1\s\src\Microsoft.Data.SqlClient\netfx\src\Microsoft\Data\SqlClient\TdsParser.cs:line 0
at Microsoft.Data.SqlClient.SqlCommand.FinishExecuteReader(SqlDataReader ds, RunBehavior runBehavior, String resetOptionsString, Boolean isInternal, Boolean forDescribeParameterEncryption, Boolean shouldCacheForAlwaysEncrypted) in D:\a\_work\1\s\src\Microsoft.Data.SqlClient\netfx\src\Microsoft\Data\SqlClient\SqlCommand.cs:line 5718
at Microsoft.Data.SqlClient.SqlCommand.RunExecuteReaderTds(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, Boolean async, Int32 timeout, Task& task, Boolean asyncWrite, Boolean inRetry, SqlDataReader ds, Boolean describeParameterEncryptionRequest) in D:\a\_work\1\s\src\Microsoft.Data.SqlClient\netfx\src\Microsoft\Data\SqlClient\SqlCommand.cs:line 5544
at Microsoft.Data.SqlClient.SqlCommand.RunExecuteReader(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, String method, TaskCompletionSource`1 completion, Int32 timeout, Task& task, Boolean& usedCache, Boolean asyncWrite, Boolean inRetry) in D:\a\_work\1\s\src\Microsoft.Data.SqlClient\netfx\src\Microsoft\Data\SqlClient\SqlCommand.cs:line 5148
at Microsoft.Data.SqlClient.SqlCommand.InternalExecuteNonQuery(TaskCompletionSource`1 completion, String methodName, Boolean sendToPipe, Int32 timeout, Boolean& usedCache, Boolean asyncWrite, Boolean inRetry) in D:\a\_work\1\s\src\Microsoft.Data.SqlClient\netfx\src\Microsoft\Data\SqlClient\SqlCommand.cs:line 2032
at Microsoft.Data.SqlClient.SqlCommand.ExecuteNonQuery() in D:\a\_work\1\s\src\Microsoft.Data.SqlClient\netfx\src\Microsoft\Data\SqlClient\SqlCommand.cs:line 1475
at Serilog.Sinks.MSSqlServer.Platform.SqlLogEventWriter.WriteEvent(LogEvent logEvent)
at Serilog.Core.Sinks.AggregateSink.Emit(LogEvent logEvent)
ClientConnectionId:c4b0f48e-f50c-4c32-8772-edb4a388538f
Error Number:208,State:1,Class:16<---
<---
It turned out it was related to
Serilog.Extensions.Loggingand there was nothing actually wrong with the sub-logger/audit configuration that I'd used.I haven't actually got a resolution to this question as such but at least I know where the problem is found. As such, I'm posting this as an answer so that anyone else using specific combination and running into this same behaviour knows the root cause and doesn't spend hours chasing around thinking it's a mistake in their config like I did.
I can work around the problem by having the code within
Namespace.We.Care.Abouttake a dependency directly on Serilog and use that for logging directly rather than the instances ofILogger<T>. Not something I wanted to do but it is an option thanks to having full control over that code as well as my calling code.I'm aware in posting this answer that this may not be a viable option for anyone who is using Serilog/Serilog.Extensions.Logging in conjunction with a third party library whose logging expects Microsoft.Extensions.Logging.ILogger instances.
As such, I have raised an issue on the serilog-extensions-logging Github repository detailing the specifics of the problem.