sql server sink 的“Guid 应包含 32 位”serilog 错误

Question

我在使用 MSSQLServer 接收器时偶尔会收到此错误。我看不出这个指南有什么问题。有任何想法吗？我已经在每个可以找到源 guid 的数据类型的地方进行了验证，它是“Guid”而不是字符串。我只是有点迷惑。

Guid 应包含 32 位数字和 4 个破折号 (xxxxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxxxx)。无法在 UserId 列中存储 。预期类型是 Guid。

本例中的 guid 是：

7526f485-ec2d-4ec8-bd73-12a7d1c49a5d
xxxxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxxxx

模板似乎与我相符？

更多详情： 这是一个偶然的问题，但当它出现时，它会出现很多。它似乎与特定的指导有关。大多数指南都很好，但一小部分有这个问题。我们的应用程序每天记录数千条消息，但这些消息没有被记录（因为问题），所以我很难准确追踪导致此错误的特定日志来自何处。但是，我们使用一个集中式的日志记录方法，运行类似这样。这个测试对我来说通过了，但它反映了我们通常用于日志记录的设置和代码，通常会成功。正如我所说，这是一个间歇性问题：

        [Fact]
        public void Foobar()
        {
            // arrange
            var columnOptions = new ColumnOptions
            {
                AdditionalColumns = new Collection<SqlColumn>
                {
                    new SqlColumn {DataType = SqlDbType.UniqueIdentifier, ColumnName = "UserId"},
                },

            };
            columnOptions.Store.Remove(StandardColumn.MessageTemplate);
            columnOptions.Store.Remove(StandardColumn.Properties);
            columnOptions.Store.Remove(StandardColumn.LogEvent);
            columnOptions.Properties.ExcludeAdditionalProperties = true;

            var badGuid = new Guid("7526f485-ec2d-4ec8-bd73-12a7d1c49a5d");

            var connectionString = "Server=(localdb)\\MSSQLLocalDB;Database=SomeDb;Trusted_Connection=True;MultipleActiveResultSets=true";

            var logConfiguration = new LoggerConfiguration()
                .MinimumLevel.Information()
                .Enrich.FromLogContext()
                .WriteTo.MSSqlServer(connectionString, "Logs",
                    restrictedToMinimumLevel: LogEventLevel.Information, autoCreateSqlTable: false,
                    columnOptions: columnOptions)
                .WriteTo.Console(restrictedToMinimumLevel: LogEventLevel.Information);
            Log.Logger = logConfiguration.CreateLogger();

            // Suspect the issue is with this line
            LogContext.PushProperty("UserId", badGuid);

            // Best practice would be to do something like this:
            // using (LogContext.PushProperty("UserId", badGuid)
            // {
                 Log.Logger.Information(new FormatException("Foobar"),"This is a test");
            // }
            Log.CloseAndFlush();
        }

自从构建此测试代码以来，我注意到的一件事是，未捕获和处置 UserId 属性的“PushProperty”。由于在这种情况下行为是"undefined"，因此我倾向于修复它，看看问题是否会消失。

全栈：

2020-04-20T08:38:17.5145399Z Exception while emitting periodic batch from Serilog.Sinks.MSSqlServer.MSSqlServerSink: System.ArgumentException: Guid should contain 32 digits with 4 dashes (xxxxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxxxx).Couldn't store <"7526f485-ec2d-4ec8-bd73-12a7d1c49a5d"> in UserId Column.  Expected type is Guid.
 ---> System.FormatException: Guid should contain 32 digits with 4 dashes (xxxxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxxxx).
   at System.Guid.GuidResult.SetFailure(Boolean overflow, String failureMessageID)
   at System.Guid.TryParseExactD(ReadOnlySpan`1 guidString, GuidResult& result)
   at System.Guid.TryParseGuid(ReadOnlySpan`1 guidString, GuidResult& result)
   at System.Guid..ctor(String g)
   at System.Data.Common.ObjectStorage.Set(Int32 recordNo, Object value)
   at System.Data.DataColumn.set_Item(Int32 record, Object value)
   --- End of inner exception stack trace ---
   at System.Data.DataColumn.set_Item(Int32 record, Object value)
   at System.Data.DataRow.set_Item(DataColumn column, Object value)
   at Serilog.Sinks.MSSqlServer.MSSqlServerSink.FillDataTable(IEnumerable`1 events)
   at Serilog.Sinks.MSSqlServer.MSSqlServerSink.EmitBatchAsync(IEnumerable`1 events)
   at Serilog.Sinks.PeriodicBatching.PeriodicBatchingSink.OnTick()

分辨率

这个问题是因为有人使用占位符创建了一条日志消息，该占位符与我们的自定义数据列同名，但传入的是字符串版本的 guid，而不是作为 guid 键入的版本。

非常简单的例子：

var badGuid = "7526f485-ec2d-4ec8-bd73-12a7d1c49a5d";
var badGuidConverted = Guid.Parse(badGuid); // just proving the guid is actually valid.
var goodGuid = Guid.NewGuid();
using (LogContext.PushProperty("UserId",goodGuid))
{
   Log.Logger.Information("This is a problem with my other user {userid} that will crash serilog. This message will never end up in the database.", badGuid);
}

快速解决方法是编辑消息模板以将占位符从 {userid} 更改为其他内容。

由于我们的代码集中在 PushProperty 发生的地方，所以我在那里进行了一些检查以监控这一点，并在将来有人再次这样做时抛出更有用的错误消息。

Answer 1

我在上面的特定代码中没有看到任何会导致问题的明显内容。在设置 Serilog 之前调用 PushProperty 的事实是我会改变的（即先设置 Serilog，然后调用 PushProperty），但这似乎不是你遇到问题的根本原因。

我的猜测是，您有一些代码路径将UserId 记录为string，而不是Guid。 Serilog 需要一个 Guid 值类型，所以如果你给它一个 string 表示 Guid 它将不起作用并且会给你那种类型的异常。

也许在您登录之前在UserId 上调用.ToString 的代码库中的某个地方？或者也许使用字符串插值，例如Log.Information("User is {UserId}", $"{UserId}");?

例如：

var badGuid = "7526f485-ec2d- 4ec8-bd73-12a7d1c49a5d";
LogContext.PushProperty("UserId", badGuid);

Log.Information(new FormatException("Foobar"), "This is a test");

或者甚至直接使用UserId 属性记录一条消息：

var badGuid = "7526f485-ec2d-4ec8-bd73-12a7d1c49a5d";
Log.Information("The {UserId} is doing work", badGuid);

上面的两个 sn-ps 都会抛出您遇到的相同异常，因为它们使用 string 值而不是真正的 Guid 值。