Feature Request - Output template

[R4cOOn]

Hi,

I'm using the MsSqlServer sink to write logs to an existing Log table. I've recently noticed that I don't get the same output in the file/console logs as in the DB logs; specifically, logged exceptions are not shown in the DB but are there in the file and console logs. Looking further, this is related to the rendering template used. Both the file and console renderers use a template looking like:

{Timestamp:yyyy-MM-dd` HH:mm:ss.fff zzz} [{Level:u3}] {Message:lj}{NewLine}{Exception}

However, the MsSqlServer sink only renders the Message.

I understand that the idea was to have the other properties (like Exception) mapped to separate columns. However, we already have an existing logging DB with associated tools, processes etc. and we can't change the structure to accomodate that particulat writer.

What I would like is the ability to provide a rendering template for the message so I can have an output on one of the DB columns similar to the one provided by the console sink.

Concrete example:

When I log an error like this: logger.Error(exception, "An exception was thrown");

The console will output:

2019-05-17 10:58:13.093 +02:00 [Error] An exception was thrown
System.InvalidOperationException: There is an error in XML document (3, 31). ---> System.FormatException: The string '2019--13' is not a valid AllXsd value.
   at System.Xml.Schema.XsdDateTime..ctor(String text, XsdDateTimeFlags kinds)
   at System.Xml.XmlConvert.ToDateTime(String s, XmlDateTimeSerializationMode dateTimeOption)
   at System.Xml.Serialization.XmlCustomFormatter.ToDateTime(String value)
   at Microsoft.Xml.Serialization.GeneratedAssembly.XmlSerializationReaderCashflowFeedMessage.Read4_CashflowFeedMessage(Boolean isNullable, Boolean checkType)
   at Microsoft.Xml.Serialization.GeneratedAssembly.XmlSerializationReaderCashflowFeedMessage.Read5_feed()

While in the DB, I've got:

An exception was thrown

And I'm completely missing the exception and stack trace.

Thanks.

[ckadluba]

Hi, and sorry for the late answer.

This sounds like a very useful enhancement. I will consider it but cannot make any promise at the moment. In the meantime we are always open for a good PR if someone has time to do it.

[gandyofthesea]

Just to throw some support on, I would also really appreciate this feature enhancement.

thanks

[flipdoubt]

I find myself needing more control over the message output as well. The OP can log the entire exception and stack trace by not providing an additional message, like logger.Error(ex, "{0}", ex). If you want to add a message to the exception you can add to Exception.Data or throw a custom exception.

In our ASP.NET Core app, unhandled exceptions appear to call logger.Error(ex, "{0}", ex) under the hood whereas I would prefer the Message column to simply contain logger.Error(ex, "{0}", ex.Message). Is there anyway to configure this behavior?

[ckadluba]

After rethinking this I came to the following concusions.

File and console are just serial streams of data. This is why those sinks need to format each log event according to an output template.

Like @R4cOOn correctly noted, with an SQL database the concept is different. The MSSQL sink can map different properties (TimeStamp, Level, Exception, Message, etc.) to different columns in the log table and therefore has no output template for the message.

But your code has always control over what goes into the Message field. So if you want to log your full exception into the Message column, you can always call logger.Error(exception, "An exception was thrown\n{ex}", exception); which should give you the full exception information including stack trace. If you only want to have the exception error message, use something like logger.Error(exception, "An exception was thrown {ExceptionMessage}", ex.Message);.

Adding an output template to the MSSQL sink would not feel right since it would be breaking the concept of mapping logevent properties to database columns while it would not provide any benefit over what you can currently do by specifying the message content.

Can you go with setting the message according to your needs?

[flipdoubt]

My initial observation about the message containing the complete stack trace in the message was actually caused by my application calling logger.Error(exception, exception.ToString), so that issue is solved.

The fact remains that our application still has no way of configuring how the MSSQL sink formats the Message column globally, as we do in most other sinks. For my use, I simply want to configure the message template as "{Message:l}" so it serializes strings without quotes rather than needing to do this in each individual message template.

In the sample line @ckadluba provided above, logger.Error(exception, "An exception was thrown {ExceptionMessage}", ex.Message);, the Message column would contain the following: 'An exception was thrown "Argument cannot be null"'. To get the output I desire, I would need to provide the string literal (:l) formatter in multiple places like logger.Error(exception, "An exception was thrown {ExceptionMessage:l}", ex.Message);.

In practice, my information log messages look like 'Job #"000098" generated Invoice #"907837" for message template "Job #{JobNumber} generated Invoice #{InvoiceNumber}". Adding the string literal formatter to each message template couples our messages to Serilog whereas I use the standard Microsoft.Extensions.Logging.ILogger.

Do I need to implement a custom ITextFormatter to control formatting of the Message column globally? Could I contribute code to make this an option we can configure in appsettings?

[ckadluba]

@flipdoubt I see your point. Unfortunately the quotes around the property names are not generated in MSSQL sink but in the serilog core (https://github.com/serilog/serilog/blob/24d623769fd7a00b348af3dac0b875bf23b3aea5/src/Serilog/Events/ScalarValue.cs#L69). Passing your own custom ITextFormatter logEventFormatter to MSSQL sink would not help because this formatter is only used when generating the LogEvent column (as documented in README.md). But I'm afraid providing a custom IFormatProvider formatProvider alone would also not help with removing the quotes. According to the source code in the serilog core linked above, you would at least also have to change the format specification in the message template, so that the property is not formatted as string. Otherwise the custom IFormatProvider is not used anyway.

Since the rendering of the message is done in serilog core, the simplest way to get rid of the quotes would be, to use the literal format specifier "l" which is not an option for you.

Would it be possible to prerender your message like this or is this also not an option? logger.Error(exception, $"An exception was thrown {ex.Message}");

[flipdoubt]

Exceptions are pre-rendered as you suggested, but it is the informational messages where we get sub-optimal messages like 'Job #"000098" generated Invoice #"907837"'. If we pre-render there, then we lose those JobNumber and InvoiceNumber properties for correlation.

[flipdoubt]

At this point, the problem is that the same message template, "Job #{JobNumber} generated Invoice #{InvoiceNumber}", renders property values without quotation marks (which I consider proper) for the Console and File sinks because the output template is "{Message:lj}". Is there really no way to achieve the same output with the MssqlServer sink?

[ckadluba]

Can you show a full sample of the log call that creates your log event containing the "Job #{JobNumber} generated Invoice #{InvoiceNumber}" message?

[flipdoubt]

As shown in the closed #319 ticket, the CombinedConfigDemo shows how the string passed into the Log.Information call on line 52 renders with quotation marks, shown below where the user name is in quotation marks.

[ckadluba]

I see what you want to achieve but unfortunately I cannot think of a reasonable way to implement that in MSSQL sink without bypassing the call to the Serilog core for rendering the message.

Any good ideas and PRs are welcome. But we have to rely on the Serilog core to render the message.

If you cannot change your message templates to remain independent of Serilog, have you looked at writing a custom enricher to do the special message template processing you need?

https://www.ctrlaltdan.com/2018/08/14/custom-serilog-enrichers/