Warning from PropertyBinder in Serilog: "Required properties not provided for: ... " about serilog-extensions-logging

[bartelink]

Best to ask stuff like this on SO rather than necroposting on 7yo threads that look a bit related if you squint really hard and don't think too much - you will get answers in minutes, not days, and nobody needs to read tangential stuff in this repo 7 years on from now.

The chances are that the issue is with your usage - the message parameter in a log call (Error) must be a message template. Anything that varies per run should be a field specified afterwards, just like with String.Format. In other words

using(LogContext.PushProperty("UserName", clientContextDto.UserName))
     Log.Error(exception, "{message} (Username {username})", message, clientContextDto.UserName);

would be correct usage.

Note that PushProperty puts the value into the LogContext - the way it gets used is by using the {Properties} field (or {UserName}) in the outputTemplate when rendering, i.e. at the point where you send it to a sink like the Console Sink, it puts it with your actual message (you seem to be hoping that {userName} might do that implicitly - it doesn't.

[nblumhardt]

Thank you for the report, looks like something we need to track down.

The tests are run from the command line; it'd be great to enable the VS runner if someone has a chance to investigate it.

[alecor191]

I noticed the same issue today. Was the root cause of this ever found?

[nblumhardt]

@alecor191 no, not so far. Any clues from your experience?

[alecor191]

@nblumhardt I created a small repro and debugged it a bit. Here what I found:

Repro scenario

Created a simple console app (.xproj) that uses MS.Extensions.Logging, Serilog, Serilog.Framework.Logging. Configured Serilog to use diagnostics logging (set SelfLog.Out property). Then log a single line using MS.Extensions.Logging ILogger:

logger.LogInformation("Some text with an argument {Argument}", 42);

Analysis

From what I see Serilog.Framework.Logging.SerilogLogger.Log does the following with the above log message:

1. It extracts the messageTemplate string from the provided {OriginalFormat} argument in the ILogValues argument
2. It retrieves the remaining arguments from ILogValues ({Argument} = 42 in the above example) and adds it Serilog by using logger.ForContext(...)
3. Finally it calls Serilog using logger.Write(level, exception, messageTemplate);.

Now the interesting part: Serilog's Logger.Write(...) method (among others) has two arguments:

• messageTemplate: Was properly set
• propertyValues: I believe here is the issue: The way Serilog.Framework.Logging adds a log message to Serilog was by providing just a message without propertyValues (see 3. above). However, Serilog seems to rely on propertyValues to determine if all property-templates in the messageTemplate have matching entries in propertyValues. As this is not the case here (we didn't provide any propertyValues, we just used .ForContext()), Serilog's validation logic thinks that something is wrong and thus adds that diagnostic entry.

Here the call stack for reference:

    Serilog!Serilog.Parameters.PropertyBinder.ConstructProperties(Serilog.Events.MessageTemplate messageTemplate = {Serilog.Events.MessageTemplate}, object[] messageTemplateParameters = {object[0]}) Line 46  C#
    Serilog!Serilog.Parameters.MessageTemplateProcessor.Process(string messageTemplate = "Some text with an argument {Argument}", object[] messageTemplateParameters = {object[0]}, out Serilog.Events.MessageTemplate parsedTemplate = {Serilog.Events.MessageTemplate}, out System.Collections.Generic.IEnumerable<Serilog.Events.LogEventProperty> properties = null) Line 38    C#
    Serilog!Serilog.Core.Pipeline.Logger.Write(Serilog.Events.LogEventLevel level = Information, System.Exception exception = null, string messageTemplate = "Some text with an argument {Argument}", object[] propertyValues = {object[0]}) Line 138   C#
>   Serilog.Framework.Logging!Serilog.Framework.Logging.SerilogLogger.Log(Microsoft.Extensions.Logging.LogLevel logLevel = Information, int eventId = 0, object state = {Microsoft.Extensions.Logging.Internal.FormattedLogValues}, System.Exception exception = null, System.Func<object, System.Exception, string> formatter = {Method = {System.Reflection.RuntimeMethodInfo}}) Line 106 C#
    Microsoft.Extensions.Logging!Microsoft.Extensions.Logging.Logger.Log(Microsoft.Extensions.Logging.LogLevel logLevel = Information, int eventId = 0, object state = {Microsoft.Extensions.Logging.Internal.FormattedLogValues}, System.Exception exception = null, System.Func<object, System.Exception, string> formatter = {Method = {System.Reflection.RuntimeMethodInfo}}) Line 38   C#
    Microsoft.Extensions.Logging.Abstractions!Microsoft.Extensions.Logging.LoggerExtensions.LogInformation(Microsoft.Extensions.Logging.ILogger logger = {Microsoft.Extensions.Logging.Logger}, string format = "Some text with an argument {Argument}", object[] args = {object[1]}) Line 277  C#
    ConsoleApp1!ConsoleApp1.Program.Main(string[] args = {string[0]}) Line 32   C#

[nblumhardt]

Ah I see - thanks for the analysis. I'll look into what we can do here.

[janodutoit]

This is a long time after this was closed, but we are currently seeing this behaviour in version 3.1.0 of the extensions - has this creeped back or are we doing something wrong?

serilogger = new LoggerConfiguration()
                        .ReadFrom.Configuration(Configuration)
                        .Enrich.FromLogContext()
                        .CreateLogger()

--->
LogContext.PushProperty("UserName", clientContextDto.UserName);
--->
Log.Error(exception, message + " Username: {UserName}");
--->

[07:16:22 INF] Required properties not provided for: Successfully fetched document data for template 'Global Variables' in document group 'GlobalVariables'. Username: {UserName}
[07:16:22 INF] Successfully fetched document data for template 'Global Variables' in document group 'GlobalVariables'. Username: [email protected]

[janodutoit]

Thanks for the reply @bartelink. I just figured using the thread that looks exactly like our issue might be a useful place to start, rather than just using SO, so we broaden our chances of success. We'll also hit up SO pretty quickly.

The funny thing is, that this does work(see the second line of the log):
Log.Error(exception, message + " Username: {UserName}");
But it also generates a warning, exactly like the original poster had, which is why we took a chance.

Our biggest issue, though, is we are using middleware to intercept the clientContextDto, so we can use the SeriLog enrichment:
.Enrich.FromLogContext()
To push the property as below:
'LogContext.PushProperty("UserName", clientContextDto.UserName);'

We are using middleware on our API, because at the time of logging, we don't have access to the clientContextDto, which is why we don't just wrap it in a using().

The weirdest though, is this used to work, until we recently updated some legacy system to the latest version of the extensions, which is when this popped up, which is also why we were wondering if c72d9e1 was accidentally merged out in a subsequent release.

But in any case, thanks for the link to message templates and I'll see if anyone replies on SO.

[bartelink]

that this does work(see the second line of the log):

Yes, but every message you log counts as a new message template, which overwhelms caches etc (dictionaries that are supposed to have max 2000 items have unbounded amounts)

The 'works' is also prone to injection - if you PushContext some auth token, and someone puts "{AuthToken}" indirectly into something you are logging, you are exposing sensitive data

TL;DR Definitely don't do this

which is why we don't just wrap it in a using().

PushProperty returns an IDisposable so you using it to remove the context. Removal doesnt always matter, but when it does, it matters a lot.

But in any case, thanks for the link to message templates and I'll see if anyone replies on SO.

If you edit in a link into your post, people will see it (have not seen your post as yet)

Bottom line is the only correct way to do all this is to do the PushProperty, and then use {UserName} or {Properties} in your message template that you pass to your sink (or, e.g. if you log as JSON, then the context properties will flow into the message, but not into the rendered text piece of the message)