serilog-mssql / serilog-sinks-mssqlserver

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

Cannot use .AuditTo with SpanId or TraceId #515

Closed Kolthor closed 4 months ago

Kolthor commented 7 months ago

Bug Report

Please clearly describe what the SQL Sink is doing incorrectly:

When using .AuditTo.MSSqlServer and including the new SpanId and TraceId standard columns, events which contains either a SpanId or TraceId breaks Serilog.Sinks.MSSqlServer, with the exception message:

Failed to emit a log event. (No mapping exists from object type System.Diagnostics.ActivitySpanId to a known managed provider native type.)

or:

Failed to emit a log event. (No mapping exists from object type System.Diagnostics.ActivityTraceId to a known managed provider native type.)

This exception does not occur when using .WriteTo.MSSqlServer, and both columns are populated in the table as expected.

The problem is that .AuditTo uses SqlLogEventWriter, which uses SqlCommand.AddParameter when adding the SpanId and TraceId: https://github.com/serilog-mssql/serilog-sinks-mssqlserver/blob/b1d8553b76ac33ec7e958992efc63ffb57a28090/src/Serilog.Sinks.MSSqlServer/Sinks/MSSqlServer/Platform/SqlLogEventWriter.cs#L57 and the values returned from StandardColumnDataGenerator.GetColumnsAndValues() are the structs System.Diagnostics.ActivitySpanId and System.Diagnostics.ActivityTraceId respectively.

.WriteTo is not affected because it uses SqlBulkBatchWriter, which maps a SqlBulkCopy to a DataTable, where the DataColumns are specified as strings, and the structs are converted when they are added.

I believe calling .ToString() on logEvent.TraceId and logEvent.SpanId in StandardColumnDataGenerator.GetColumnsAndValues() should fix the issue: https://github.com/serilog-mssql/serilog-sinks-mssqlserver/blob/b1d8553b76ac33ec7e958992efc63ffb57a28090/src/Serilog.Sinks.MSSqlServer/Sinks/MSSqlServer/Output/StandardColumnDataGenerator.cs#L53-L56

Please clearly describe the expected behavior:

Both columns are populated in the table, with no exceptions or missing events.

List the names and versions of all Serilog packages used in the project:

Target framework and operating system:

[x] .NET 6 [ ] .NET Framework 4.8 [ ] .NET Framework 4.7 [ ] .NET Framework 4.6

OS: Windows 11 Version 22H2 (OS Build 22621.3007)

Provide a simple reproduction of your Serilog configuration code:

// Serilog.Sinks.MSSqlServer ColumnOptions
var columnOptions = new ColumnOptions();
columnOptions.Store.Remove(StandardColumn.Properties);
columnOptions.Store.Add(StandardColumn.LogEvent);
columnOptions.Store.Add(StandardColumn.TraceId);
columnOptions.Store.Add(StandardColumn.SpanId);

// Configure Serilog
builder.Services.AddLogging(builder =>
    builder.AddSerilog(
        logger: new LoggerConfiguration().Enrich.FromLogContext()
                                         .MinimumLevel.Is(Serilog.Events.LogEventLevel.Debug)
                                         .AuditTo.MSSqlServer(@"Server=.\SqlExpress;Database=__SerilogTest;Trusted_Connection=True;Encrypt=False;",
                                                              new MSSqlServerSinkOptions
                                                              {
                                                                  TableName = "EventLog",
                                                                  AutoCreateSqlDatabase = true,
                                                                  AutoCreateSqlTable = true,
                                                              },
                                                              columnOptions: columnOptions
                                         ).CreateLogger(),
        dispose: true
    ).Configure(options => options.ActivityTrackingOptions = ActivityTrackingOptions.TraceId | ActivityTrackingOptions.SpanId)
);

Provide a simple reproduction of your Serilog configuration file, if any:

N/A

Provide a simple reproduction of your application code:

https://github.com/Kolthor/SerilogTest

ckadluba commented 7 months ago

Hello @Kolthor!

Thank you for reporting this issue and for the thorough analysis. I will look into itnas soon as I can. Hopefully within the next 2 weeks.

Cheers, Christian

vui611 commented 4 months ago

Hi @ckadluba Is there any progress on this ticket? Based on what @Kolthor described, it seems to be a very easy fix, doesn't it? Regards

ckadluba commented 4 months ago

Sorry for the delay. I have not enough bandwidth for testing the proposed fix at the moment. But we are always happy if someone helps us out with a PR. We could review this quickly and merge if it is good.

vui611 commented 4 months ago

@ckadluba Thank you for your fast response. Please check the quick PR here :) #535

ckadluba commented 4 months ago

@vui611 Thank you very much for the PR. It was just merged into the dev branch. 🫶

@Kolthor Thanks a lot for reporting this and for the detailed bug analysis.

A dev version of the sink was built and published on nuget.

https://www.nuget.org/packages/Serilog.Sinks.MSSqlServer/6.6.1-dev-00077

It would be great if you could take it for a spin and test the fix with this version or with the current code in the dev branch.

Naturally the fix will also go into the next regular release (when we merge dev into main). But since there are one or two significant open bugs, I would like to wait until we have them fixed too.

vui611 commented 4 months ago

@ckadluba I can confirm the version 6.6.1-dev-00077 works well now. I can use AuditTo() without any exception and 2 columns TraceId, SpanId are written to the database. Thank you.

Screenshot 2024-05-01 at 9 47 51 am