使用Serilog子记录器实现审计日志时异常未向外抛出的问题

问题背景 #

我尝试用Serilog实现审计日志：仅将Namespace.We.Care.About命名空间下的日志事件通过子记录器输出到SQL Server的LogTable，要求写入失败时立即抛出异常。但测试时（未提前创建日志表），异常仅出现在Serilog的SelfLog中，并未传播到应用程序代码。同时使用了Serilog.Extensions.Logging兼容Microsoft.Extensions.Logging，目标日志事件由该组件生成。

当前Serilog配置 #

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();

SelfLog中的异常信息 #

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<---
<---

问题原因 #

1. Microsoft.Extensions.Logging接口约束：Serilog.Extensions.Logging适配器严格遵循Microsoft.Extensions.Logging的ILogger规范——Log方法不会抛出任何异常，所有异常都会被捕获并写入Serilog的SelfLog，不会传递到应用程序代码。
2. Audit配置嵌套冗余：当前配置中，外层用.AuditTo.Logger定义审计子记录器，内层子记录器又调用.AuditTo.MSSqlServer，虽然Audit模式设计为失败时抛出异常，但最终被适配器的异常拦截逻辑覆盖。

解决方案 #

方案1：直接使用Serilog原生ILogger（推荐） #

审计日志对可靠性要求高，建议绕过Microsoft.Extensions.Logging适配器，直接使用Serilog的ILogger记录目标日志，这样Audit模式的异常会直接抛出到应用程序中：

// 获取指定命名空间的Serilog日志实例
var auditLogger = Log.ForContext("SourceContext", "Namespace.We.Care.About");
auditLogger.Information("审计日志内容");

方案2：自定义SelfLog异常处理（适配Microsoft.Extensions.Logging场景） #

如果必须使用Microsoft.Extensions.Logging的ILogger，可以监听Serilog的SelfLog，在检测到审计相关异常时手动抛出（需谨慎，避免影响正常日志流程）：

// 应用启动时配置SelfLog
Serilog.Debugging.SelfLog.Enable(message =>
{
    // 筛选审计日志相关的异常
    if (message.Contains("Namespace.We.Care.About") && message.Contains("Invalid object name 'dbo.LogTable'"))
    {
        throw new InvalidOperationException("审计日志写入失败", new Microsoft.Data.SqlClient.SqlException("Invalid object name 'dbo.LogTable'"));
    }
    // 其他异常正常输出到控制台
    Console.WriteLine(message);
});

方案3：简化Serilog配置（优化嵌套结构） #

去掉子记录器中的.AuditTo，直接配置Sink为同步写入模式（虽然无法解决适配器捕获异常的问题，但可以简化配置逻辑）：

var logger = new LoggerConfiguration()
    .MinimumLevel.Debug()
    .AuditTo.Logger(l => 
    {
        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);

        l.Filter.ByIncludingOnly(Matching.FromSource("Namespace.We.Care.About"))
         .WriteTo.MSSqlServer(
             connectionString: ConfigurationManager.ConnectionStrings["Database"].ConnectionString,
             sinkOptions: sqlSinkOpts,
             columnOptions: sqlSinkColOpts,
             restrictedToMinimumLevel: LogEventLevel.Verbose,
             batchPostingLimit: 1); // 禁用批量，立即同步写入
    })
    .CreateLogger();

内容的提问来源于stack exchange，提问作者Mark Embling