Custom Columns Are Being found as null when doing runtime configuration

[Joel-S-Black]

Bug Report / Support Request Template

If you are opening a feature request, you can ignore this template. Bug reports and requests for assistance usually require the same basic information described below. This will help us more quickly reproduce and investigate the problem you're reporting. (If you are using Serilog.Sinks.MSSqlServerCore, that package is deprecated, please switch to Serilog.Sinks.MSSqlServer before reporting an issue.)

Please clearly describe what the SQL Sink is doing incorrectly:

SQL Sink is missing the Level property when trying to insert into the table. The selflog is saying " Unable to write 1 log events to the database due to following error: Column 'type' does not allow nulls." . While the column "type" does not allow nulls, the column "type" is configured to bind to the "Level" property. Per the sink documentation, the standard property "Level" must be nvarchar, but the system I am integrating to has varchar fields, so I created the columns per documentation. I have tried the audit instead of writeto, and I get a different error.

Please clearly describe the expected behavior:

SQL Sink should be following the configuration, successfully find the properties in the Events, and persist them to the database

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

• Serilog: 2.8
• Serilog.Sinks.MSSqlServer: 5.6.0
• Serilog.AspNetCore: 3.4.0
• Serilog.Enrichers.Environment: 2.1.3
• Serilog.Settings.Configuration: 3.1.0
• SerilogTimings: 2.3.0

Target framework and operating system:

[ x ] .NET Core 3.1 [ ] .NET Core 2.0 [ ] .NET Framework 4.7 [ ] .NET Framework 4.6.x [ ] .NET Framework 4.5.x OS: Windows 10 Professional

Provide a simple reproduction of your Serilog configuration code:

https://github.com/Joel-S-Black/repros.serilog.sinks.mssqlserver.exactproblem/blob/master/Program.cs

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

https://github.com/Joel-S-Black/repros.serilog.sinks.mssqlserver.exactproblem/blob/master/appsettings.json https://github.com/Joel-S-Black/repros.serilog.sinks.mssqlserver.exactproblem/blob/master/appsettings.Development.json

Provide a simple reproduction of your application code:

https://github.com/Joel-S-Black/repros.serilog.sinks.mssqlserver.exactproblem/blob/master/Program.cs

Here is the create statement for the database table:

`CREATE TABLE [dbo].[logs]( [id] [int] IDENTITY(1,1) NOT NULL, [type] varchar NOT NULL, [logDate] [datetime] NOT NULL, [eventid] [int] NOT NULL, [title] varchar NULL, [category] varchar NULL, [message] varchar NULL, [exceptionText] varchar NULL, [computer] varchar NULL, [registeredAppId] varchar NULL, CONSTRAINT [IDX_C_Logs_Id] PRIMARY KEY CLUSTERED ( [id] ASC, [logDate] ASC )WITH (FILLFACTOR = 90) ) GO

ALTER TABLE [dbo].[logs] ADD CONSTRAINT [DF_logs_logDate] DEFAULT (getutcdate()) FOR [logDate] GO `

To see this in action, please go to my repo, download the code, create the table on your local table, alter the connection string, and run it.

[ckadluba]

After a fist check, it seems that the PropertyName functionality was only added for System.Configuration based initialization (https://github.com/serilog/serilog-sinks-mssqlserver/pull/268). System.Configuration in this sink only applies to consumers targeting .NET 2.0 or .NET Framework 4.6.1. But since your sample uses .NET Core 3.1 Microsoft.Extensions.Config is used.

[ckadluba]

Okay, after revisiting the PR again and also the issue #182 that originated it, I think you interpret the functionality of PropertyName different from how it actually works. In your sample, if you set the PropertyName of the additional column named type to "Level" this does not make the sink map the default property Level to the additional column type. It only means you can define a custom property name that is mapped to a custom additional column where the custom property is different from the column name. So you could fill the type column from a property with a name other than "type". It was actually implemented to adapt to existing large code bases that use certain property names and are too hard to change. It was not implemented to adapt to existing database schemas like in your case.

If you just need to map a standard property to a column name different from the property name you could use code like this.

columnMappings.Level.ColumnName = "type";

But if the type is also different, then this would not really help. So if you need to fill your additional custom type from standard property Level and also covert it's datatype, you should take a look at Serilog Enrichers. They can be used to enrich/fill properties in the log event object before it gets written to the sink. Probably you can use this to copy the contents of the Level standard property over to the type property which is defined by and mapped to the additional column type.

[Joel-S-Black]

My understanding is based on the documentation for the specific version: https://github.com/serilog/serilog-sinks-mssqlserver/tree/v5.6.0#custom-property-columns . Are you saying definitively that there is no way with this Sink to divert the "Level" property from the log event into a column of my choosing? The paragraph "Unlike previous versions of the sink, Standard Column names are not reserved. If you remove the Id Standard Column from the ColumnOptions.Store list, you are free to create a new custom column called Id which the sink will treat like any other custom column fully under your control." seemed to indicate that the log event properties like "Properties" and "Level" could be mapped into custom fields. but you seem to be saying that is not the case. If my understanding of what you are saying is true, those caveats should be spelled out in the beginning of the document.

As for using enrichers for this, I'm looking into how to find the standard properties and divert them, but I have not found any examples where "Level" is renamed as something else.

[ckadluba]

There might be a misconception about custom properties.

The MSSQL sink knows standard properties like Message, Level, DateTime, etc. Those are the properties which are predefined by the API and their values are produced by Serilog itself. The list of standard properties can be found here: https://github.com/serilog/serilog-sinks-mssqlserver/blob/dev/src/Serilog.Sinks.MSSqlServer/Sinks/MSSqlServer/StandardColumn.cs.

Then there are custom properties (or additional properties). They can be defined by the user to add additional custom fields to the log event.

Both, standard properties and custom properties can be mapped to columns in the database which the user can choose. If you only want to map the Level standard property to a column called type this is very easy to do. You can just use code like is showed above:

columnMappings.Level.ColumnName = "type";

You can also set the type and length, nullability etc. like this. There are samples and explanations of this in the readme, working sample programs demonstrating that in the samples folder and also tests asserting this.

But standard properties have certain limitiations regarding datatypes, nullability etc. If that is an issue in your scenario, you should look at enrichers. Here you find a simple primer with a small sample on enrichers: https://www.ctrlaltdan.com/2018/08/14/custom-serilog-enrichers/.

For instance you could add a custom property type and map it to your type column. To populate the Type custom property from the content of the Level standard property, you could add a TypeEnricher along the lines of this (the rest can be found on the page linked above).

public void Enrich(LogEvent logEvent, ILogEventPropertyFactory propertyFactory)
{
    var levelValue = // Get and convert value from logEvent.Level ...
    var typeProperty = propertyFactory.CreateProperty("Type", levelValue.);
    logEvent.AddPropertyIfAbsent(propertyFactory);
}

But like I said in the beginning, probably you don't even need Enrichers or a custom property and a almost certainly your don't need PropertyName in your case.

[Joel-S-Black]

I tried the enricher and I debugged it and the properties appear to be added. My other log sinks are working, but I'm getting the error message: "Unable to write 1 log events to the database due to following error: The given ColumnMapping does not match up with any column in the source or destination." from MsSqlServerSinks.

Here is the repro .

The original columns work, however, so I thinking that you cannot eliminate standard columns.

[Joel-S-Black]

I found that if I use "AuditTo" instead of "WriteTo" on MsSqlServer (line 155 of Program.cs from https://github.com/Joel-S-Black/repros.serilog.sinks.mssqlserver.exactproblem/tree/same-sequence-with-enricher-for-new-columns ), it works.

[ckadluba]

I debugged your latest sample and found multiple problems in that code. But the most important thing seems to be that the SQL create table script you posted above is missing max size parameters for all the varchar columns which leads a table having all those columns created with a max size of 1.

So if I used your sample with that table, I ran into an error stating that the column mapping is wrong. This is the exception that is thrown by the bulk copy API of ADO.NET in many cases where there is a mismatch between columns definition in the database and in the object used for the bulk insert. Even when changing the sample to use AuditTo we get an error because of this.

So you have to specify a max size for your varchar columns in the create table statement.

The next problem is, that you add the StandardColumn.Id to the column mapping In this line.

columnMappings.Store.Add(StandardColumn.Id);

This means the sink tries to insert a column named Id which does not exist in your table. Just leave that line away which keeps the column mapping for the Id property removed (you remove them all in the line before that). Instead use the enricher to write the log event ID generated by Serilog into your eventid column. Provide a default value 0 for cases where this property is unavailable because your eventid column in not nullable.

private void SetEventId(LogEvent logEvent, ILogEventPropertyFactory propertyFactory)
{
    const string eventIdPropertyName = "EventId";
    var eventId = 0;
    if (logEvent.Properties.ContainsKey(eventIdPropertyName))
    {
        var eventIdProperty = (StructureValue)logEvent.Properties[eventIdPropertyName];
        var eventIdValue = (ScalarValue)eventIdProperty.Properties[0].Value;
        eventId = (int)eventIdValue.Value;
    }

    logEvent.AddPropertyIfAbsent(propertyFactory.CreateProperty(MagicValues.LogPropertyNames.EventId, eventId));
}

At this point I also have to mention, that you mistyped the name of the "eventid" column in the mapping as "eventId".

columnMappings.AdditionalColumns.Add(new SqlColumn { ColumnName = "eventId", AllowNull = false, DataType = SqlDbType.Int, PropertyName = MagicValues.LogPropertyNames.EventId });

Another problem is the composite primary key for your table. It consists of the columns id and logDate. id is defined as a DB generated identity so its value cannot be provided by the sink during the insert operation. logDateon the other hand should be provided by the sink from the log events timestamp. But from what I saw during the tests, it is not possible to insert logDate while having the id field generated by the DB as an identity. Since id is an identity I would suggest to make this the only field of the primary key. I altered your PK definition in the create table SQL script to make that happen.

CONSTRAINT [IDX_C_Logs_Id] PRIMARY KEY CLUSTERED
(
[id] ASC
--,
--[logDate] ASC
)WITH (FILLFACTOR = 90)
)
GO

The mapping for the column exceptionText had AllowNulls = false although the column in the table is defined as nullable. Additionally this mapping should also specify a DataLength just like the other nvarchar columns. I changed the mapping as follows.

columnMappings.AdditionalColumns.Add(new SqlColumn { ColumnName = "exceptionText", AllowNull = true, DataType = SqlDbType.VarChar, DataLength = 1000, PropertyName = MagicValues.LogPropertyNames.ExceptionText });

The mapping for column computer also had the wrong nullability and needed to be changed like this.

columnMappings.AdditionalColumns.Add(new SqlColumn { ColumnName = "computer", AllowNull = true, DataType = SqlDbType.VarChar, DataLength = 50, PropertyName = MagicValues.LogPropertyNames.Computer });

After fixing all this, your sample worked and logs were written to the table.

Here is the SQL script I used based on your initial version.

CREATE TABLE [dbo].[logs](
[id] [int] IDENTITY(1,1) NOT NULL,
[type] varchar(50) NOT NULL,
[logDate] [datetime] NOT NULL,
[eventid] [int] NOT NULL,
[title] varchar(100) NULL,
[category] varchar(50) NULL,
[message] varchar(1000) NULL,
[exceptionText] varchar(1000) NULL,
[computer] varchar(50) NULL,
[registeredAppId] varchar(50) NULL,

CONSTRAINT [IDX_C_Logs_Id] PRIMARY KEY CLUSTERED
(
[id] ASC
--,
--[logDate] ASC
)WITH (FILLFACTOR = 90)
)
GO

ALTER TABLE [dbo].[logs] ADD CONSTRAINT [DF_logs_logDate] DEFAULT (getutcdate()) FOR [logDate]
GO

I'm also attaching my fixed version of your sample here: repros.serilog.sinks.mssqlserver.exactproblem-same-sequence-with-enricher-for-new-columns-fixed.zip (I only changed Program.cs and LogTableEnricher.cs).

[Joel-S-Black]

Thank you very much! You are correct, my table definition provided in this issue is incorrect, sorry about that. Here is the corrected definition:

` CREATE TABLE [dbo].[logs]( [id] [int] IDENTITY(1,1) NOT NULL, [type] varchar NOT NULL, [logDate] [datetime] NOT NULL, [eventid] [int] NOT NULL, [title] varchar NULL, [category] varchar NULL, [message] varchar NULL, [exceptionText] varchar NULL, [computer] varchar NULL, [registeredAppId] varchar NULL, CONSTRAINT [IDX_C_Logs_Id] PRIMARY KEY CLUSTERED ( [id] ASC, [logDate] ASC )WITH (PAD_INDEX = OFF, STATISTICS_NORECOMPUTE = OFF, IGNORE_DUP_KEY = OFF, ALLOW_ROW_LOCKS = ON, ALLOW_PAGE_LOCKS = ON, FILLFACTOR = 90) ON [PRIMARY] ) ON [PRIMARY] TEXTIMAGE_ON [PRIMARY] GO

ALTER TABLE [dbo].[logs] ADD CONSTRAINT [DF_logs_logDate] DEFAULT (getutcdate()) FOR [logDate] GO `

The missing pieces were

• not matching the case of the column name in C# to the case of the column name in SQL Server (I always forget that the case insensitivity of SQL Server does not cross the threshold into C#)
• and that the identity column for "id" was a problem. After I removed the "Id" column, the default constraint kicked in for the logDate column, as did the identity insert.
• having the wrong nullability defined.

After I fixed all those, it worked! Here is the working solution: https://github.com/Joel-S-Black/repros.serilog.sinks.mssqlserver.exactproblem/tree/problem-solved

[ckadluba]

I'm glad I could help. :)