Runtime: Logging structured data without it appearing in the text message

[roji]

Am looking for some guidance here, or at least confirmation that I understand things right...

Currently, if I want to use the extension methods (e.g. LogDebug), it seems that in order to log some piece of structured data it must be referenced from the message - this seems problematic in several scenarios.

First, when using a logging framework such as NLog, it is standard practice to leave the layout of the text message to NLog (user-configurable). Requiring me to embed all structured data in the message text hands off a fully-formed message to NLog, stripping it of one of it's main responsibilities (layouting).

Also, in many scenarios there's a lot of structured context that may be interesting to users in some cases, but that doesn't mean it's always interesting and should get included in the text of each and every message. This causes very large log messages with clutter and info nobody really wants (although people may still want the option of looking up these details in the structured data attached to the message).

I understand that I don't have to use the extension methods and can roll my own, but I'd like confirmation to the above, and also your opinion on this.

[herecydev]

First, when using a logging framework such as NLog, it is standard practice to leave the layout of the text message to NLog (user-configurable). Requiring me to embed all structured data in the message text hands off a fully-formed message to NLog, stripping it of one of it's main responsibilities (layouting).

I would probably make a custom ILogger, as you're allowed to give it any TState and let that decide on the format (can be user-configurable), it can even enhance the messages with additional information (current time, machine name, etc) so that the caller doesn't need to supply it.

Also, in many scenarios there's a lot of structured context that may be interesting to users in some cases, but that doesn't mean it's always interesting and should get included in the text of each and every message. This causes very large log messages with clutter and info nobody really wants (although people may still want the option of looking up these details in the structured data attached to the message).

This one's a little weird and I'm not sure I totally get it. But I think once again, you can switch on the LogLevel within your custom logger and decide what's appropriate. With that said, surely the calling code has a much better understanding of verbosity than a downstream consumer. You should really use the LogLevel to filter out what's too noisy; a syslog driver will probably log everything whilst a console just information and above.

I see it as the calling code provides as much meaningful data as it can, the logger's can optionally enhance that with additional data but ultimately filter that down based on the appropriate destination. Bearing in mind, we have technologies like Elastic Search to perform more advanced features.

[roji]

First, when using a logging framework such as NLog, it is standard practice to leave the layout of the text message to NLog (user-configurable). Requiring me to embed all structured data in the message text hands off a fully-formed message to NLog, stripping it of one of it's main responsibilities (layouting).
I would probably make a custom ILogger, as you're allowed to give it any TState and let that decide on the format (can be user-configurable), it can even enhance the messages with additional information (current time, machine name, etc) so that the caller doesn't need to supply it.

I'm not sure that a custom logger is necessary - the provided Logger's Log method already accepts any TState and formatter... So this is definitely resolvable, it's just not compatible with the "standard" extension methods and requires implementing a layer for something that seems pretty basic/standard.

This one's a little weird and I'm not sure I totally get it. But I think once again, you can switch on the LogLevel within your custom logger and decide what's appropriate.

The issue isn't what log events should be logged - which is what LogLevel is about - but rather what extra information is included in the textual message that's emitted in the event.

With that said, surely the calling code has a much better understanding of verbosity than a downstream consumer. You should really use the LogLevel to filter out what's too noisy; a syslog driver will probably log everything whilst a console just information and above.

I don't think that's necessarily true... Coming from NLog, it's quite frequent for applications to log quite a thin textual message, but to include lots of contextual information with it. The calling code should make available the information, but whether the textual message needs to include it seems more like a user configuration choice. This allows you to search for log records (in a tool like Kibana) without making the message itself heavier.

The point is that there are two "usage patterns" for consuming logs. On the one hand, you want to be able to search/filter for logs - this is where the structured information is important. On the other hand, you want to be able to simply browse - read records line-by-line, say around a timestamp or some event - and at that point the message text (and its terseness!) is important. It seems the current approach leads to very heavy messages as every piece of information you may want to search on also needs to get included in the text.

I see it as the calling code provides as much meaningful data as it can, the logger's can optionally enhance that with additional data but ultimately filter that down based on the appropriate destination. Bearing in mind, we have technologies like Elastic Search to perform more advanced features.

I think that's different - enriching an application-provided event with generic information (thread/process id, machine name...) is very different from fields provided by the application itself. In this issue I'm talking about the latter only.

[herecydev]

The calling code should make available the information, but whether the textual message needs to include it seems more like a user configuration choice.

I'll preface this with I'm not an expert, nor have I used NLog. Given the following scenario, where some command failed and you want to log the failure, the command that was used and the exception that was raised:

c# catch(Exception ex) { _logger.LogInformation("DB Command failed {0} {1}", command, ex); }

You could have a file logger that adds on the current date, formats the message with the parameters to produce something like: "14/12/2016 | DB Command failed | Select * from foo | foo does not exist".
You could then equally have a logger that adds on the current time but drops the parameters for terseness: "9:20:16 | DB Command failed"

Does that satisfy the 2 "ends of the spectrum"? Or am I missing the use case? Also I don't think the DI/Logging libraries are meant to be prescriptive, could you use the NLog extensions to have the behavior you're after working with the ILogger abstractions?

[roji]

Your example of prefacing the date is what I referred to earlier as "generic information" that can indeed be added by any threading package - this kind of info includes thread ID, hostname or anything else that doesn't need to come from the application. You're right that this case isn't an issue.

The kind of info I'm talking about is stuff that only the application knows about. For example, an event may have info such as server IP, port, transaction ID, etc. These can't be added by NLog (or any other package), because only your application knows about them. On the other hand, it doesn't necessarily make sense to include them in the text of each and every log message we log. So we want the information to be available in case want to search for, say, all events we've had with a certain server IP; on the other hand, shoving the server IP into each and every log text is unnecessary and makes logs harder to understand.

In NLog (and other logging packages), the application would log a text message, in addition to the bundle of structured data. The user's NLog configuration would render all this information: a user could decide to prefix every message with the current timestamp (generic info), but also with the server IP, the port, or any other info in the structured bundle.

I hope I'm making sense and that the use case is more or less clear...

[herecydev]

I think so, you want the application to supply as much information to the logger as possible and for the logger to be configured to either be verbose/terse depending on the situation.

You could have a file logger that adds on the current date, formats the message with the parameters to produce something like: "14/12/2016 | DB Command failed | Select * from foo | foo does not exist".
You could then equally have a logger that adds on the current time but drops the parameters for terseness: "9:20:16 | DB Command failed"

Why wouldn't this satisfy your requirements? You could have a syslog logger for the first example and a console logger for the latter? The formatting/discarding of information that can happen in the logger could easily be user-configurable (DI in some templates), this can even be done at a per-class level because we have ILogger<T>.

[roji]

I think so, you want the application to supply as much information to the logger as possible and for the logger to be configured to either be verbose/terse depending on the situation.

Right, configured by the user.

Why wouldn't this satisfy your requirements? You could have a syslog logger for the first example and a console logger for the latter? The formatting/discarding of information that can happen in the logger could easily be user-configurable (DI in some templates), this can even be done at a per-class level because we have ILogger.

Because currently it seems that it's impossible to use the extension methods to pass structured information without also including it in the message text... The extension methods parse the message text, looking for named variables, and matching those to the params array. So when using the "standard" extension methods, all structured data must also be included in the message text.

[herecydev]

I'm with you, I think it boils down to "this works for most people". The default extensions use the FormattedLogValues but I don't think that will work as the original message is private. So you wouldn't be able to selectively remove things. Would probably have to create another extension like LogStructureInformation that passes through the message format and the args. Then in combination with customer loggers or Nlog you should be able to go from there.

I think if this was public you would be fine. The out the box loggers would continue to work and be simple for most scenarios, and you can add another logger to work with the format/information passed in as discussed above.

[roji]

Sorry for disappearing :)

Making _originalMessage accessible is a possible approach. Note that it's also possible to simply avoid the extension methods and call Logger.Log() directly, controlling exactly what state object is passed and how it's formatted.

So users aren't exactly limited, it's just that the default way of doing things is basically very inspired from Serilog, and doesn't really take into account other approaches such as NLog's.

[herecydev]

Note that it's also possible to simply avoid the extension methods and call Logger.Log() directly, controlling exactly what state object is passed and how it's formatted.

It is, but telling people not to use these nice, convenient extension LogInformation, LogError etc and instead use Log(LogLevel.Information, 0, new FormattedLogValues(message, args), null, (m, e) => m.ToString()) is far from intuitive. It would be preferable to make FormattedLogValues have that public property and then people can start extending on it.

[roji]

Looking at it again, I'm not sure I understand how making this property public addresses this issue. If I understand correctly, all that would do would be to provide access to the original format string, the one with names in it. Also, it's not clear at what point users would be able to interact with this property: FormattedLogValues is created internally when LogXXX and immediately passed down to Logger.Log... Can you provide more detail on how this would work?

[herecydev]

Because in your custom ILogger you would have access to: "DB Command failed {0} {1} and Select * from foo and foo does not exist. You've got everything you need to either log everything or strip some of the more verbose things out. I don't envisage users interacting with neither the FormattedLogValues or Log(a, b, c, d, e) directly. Just using the extensions and letting the different loggers do all the hard work.

[roji]

I don't think that solves it... If you continue using the standard extension methods, you continue writing code like this:

c# logger.LogDebug(eventId, exception, "Executing: {Sql}", sql, transactionId, someOtherInterestingBit);

Your custom ILogger indeeds get both the original string (Executing: {Sql}) and the processed string (Executing: {0}). transactionId and someOtherInterestingBit are there in the params object array, but there's nothing saying how to name them. The point is that the extension methods depend on the formatter string to reference (i.e. name) all structural data.

In other words, the problem seems to be with the extension methods' API (which follows Serilog) and does not allow for structured data that's not referenced in the format string. An alternate API would simply allow passing in a Dictionary, which would represent the structured data. The formatter string would still contain named references to the Dictionary's keys (i.e. names), and integrate their corresponding values in the textual message. But nothing would prevent us from having additional key/value pairs in the Dictionary which aren't referenced in the format string.

[herecydev]

That's correct, this was on the assumption that they were passed in the correct order and with the correct amount. Which probably holds true for most cases. An overloaded extension with a dictionary would be ideal though.

[roji]

@herecydev I don't think so... the point is that with the extension methods there is no way to name a structured parameter without referencing it from the format string... It's not a question of correct order - no matter how you implement your ILogger, with the extension methods you get a string with name references, and a nameless array of objects. The first objects in the array are named via the string - and also appear in the formatted text message - while the remaining ones are completely anonymous and therefore can't really be part of the structured data logged alongside the message.

[herecydev]

This was assuming you were using this:
c# catch(Exception ex) { _logger.LogInformation("DB Command failed {0} {1}", command, ex); }
where you aren't using named references. Otherwise if you need the named references, I only see the dictionary being the working solution.

[herecydev]

I actually think this is possible: See this line shows that you can get the OriginalFormat out of the values collection. Then using these lines you can enumerate through the named values thanks to this class. Note that you have to explicitly ask for the Count - 1? to get the OriginalFormat out.

It does therefore look like with the existing extension methods, and your own custom loggers, you have the potential, through DI'ing the templates, to do what you're asking.

[roji]

I might not be explaining myself clearly...

My problem is the very fact that your string must contain named reference to the positional parameter list (which, by their nature, are otherwise unnamed). What you're showing allows me to access values that have been named by the string. What I'd like to do is include structured values - with names I choose - without referencing them in the format string. That seems impossible to do without adding an overload that accepts a Dictionary.

[herecydev]

If I understand what you're after then no it won't be possible at all. You can't "know" what the parameters are at the logger without either naming them in the format string (and thereby deducing through order), or passing KVPs through.

[roji]

Yeah, that's my understanding as well. I opened this issue to propose that Microsoft.Extensions.Logging provide a solution for that, e.g. via overloads that accept that accept a Dictionary.

[roji]

In other words, if the team feels like it's something you need to have, I could submit a PR.

[herecydev]

Cool... we got there :) It sounds like an interesting addition.

[Ralstlin]

@roji I come here looking for exactly the same thing, I was trying to create a loggerProvider that use MongoDB driver to log structured data into mongo, sadly I found the same as you, logging params without naming them in the message like: _logger.LogTrace("Creating new user", UserData, SystemData, WhatEver); will not display these params in the Ilogger.Log because LogValuesFormatter.GetValue() https://github.com/aspnet/Logging/blob/dev/src/Microsoft.Extensions.Logging.Abstractions/Internal/LogValuesFormatter.cs get only objects from _valueNames that is a list of brackets variables in the formatted string. For that reason I implemented my own extended versions:

```c#
public class FormattedLogValuesExposed : FormattedLogValues
{
public readonly object[] Parameters;
public FormattedLogValuesExposed(string format, params KeyValuePair[] values) : base(format, values.Select(a => a.Value)
{
Parameters = values;
}
}

Then I only need to use it like: 

```c#        
public static void LogTraceAsync(this ILogger logger, string message, Exception exception, EventId eventId, params KeyValuePair<string, object>[] args)
        {
            Contract.Requires<ArgumentNullException>(logger == null, "Logger cannot be null.");

            Task.Run(() =>
            {
                logger.Log<FormattedLogValuesExposed>(
                    LogLevel.Trace,
                    eventId,
                    new FormattedLogValuesExposed(message, args),
                    exception,
                    (state,ex) => state.ToString() );

            }).ConfigureAwait(false);
        }

and on my Ilogger implementation I just do:

```c#

    public void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Exception exception, Func<TState, Exception, string> formatter)
    {
        Contract.Requires<ArgumentNullException>(formatter == null, $"Formatter: {nameof(formatter)} cannot be null");
        if (IsEnabled(logLevel))
        {
            var message = formatter(state, exception);

            var stateExposed = state as FormattedLogValuesExposed;

            if (stateExposed != null )
            {
                var json = JsonConvert.SerializeObject(stateExposed.Parameters);

                // log parameters into db
            }
        }
    }

using it:

```c#

logger.LogTraceAsync("Email sent logging test",
    new KeyValuePair<string, object>("TO", new { Email = "[email protected]", UserID = 1}),
    new KeyValuePair<string, object>("CC", new { Email = "[email protected]", UserID = 2 }),
    new KeyValuePair<string, object>("BCC", new { Email = "[email protected]", UserID = 3 })
    );

Hope they implement something like this.

[roji]

@Ralstlin yeah, this is pretty much what @herecydev proposed here. The problem, as I wrote further down, is that you simply have an unnamed list of object parameters, whereas in structured logging you usually want to attach names to them - and that's not possible. The real solution here would be to simply pass a Dictionary<string,object>, but that means dumping the standard extension methods (e.g. LogDebug).

[roji]

Yeah. To be fair, having structured data that isn't referenced in the string message may not be something everyone needs - it's OK to have other Log* extension methods with dictionary overloads.

What I'd like to know is whether a pull request adding these dictionary-using extensions would be accepted...

[herecydev]

I don't think they would detract from what's there. I would imagine the official standpoint would have to consider maintenance overhead. I would like to see this included though.

[Ralstlin]

I see what you mean. Because I am using a Fire and Forget approach for my Async logging, I really could use reflection to get a Name, but it have too many complex issues (same type logged twice, Anonymous types, etc) I modified the previous code to use KeyValuePair, is not as clean as before but is not as bad to discard the option. I prefer to work directly with KeyValuePair because I dont see the benefit of having uniques keys for logging.

[brettsam]

I wanted to chime in here -- I was looking for this same functionality and came across this issue. I created this class and thought it may be useful: https://gist.github.com/brettsam/baf21619b280912159b4178650294fcd.

My ILoggers don't care whether they're getting a FormattedLogValues or my custom class -- in both cases they're able to:

• call ToString() to get a formatted message
• cast to IEnumerable<KeyValuePair<string, object>> to get all of the key-value pairs.

I could write some LogInfo/LogDebug/etc extensions to make it even easier, but here's how I use it:

LogValueCollection payload = new LogValueCollection("logging {key}", new[] { "value" }, someDictionaryOfAdditionalProperties);
logger.Log(LogLevel.Information, 0, payload, null, (s, e) => s.ToString());

[AlanBarber]

+1 to running into this issue while working on a custom logger.

As a workaround, I found that I could cast the state as a FormatttedLogValues object and then run a foreach over it to get a the properties attached.

public void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Exception exception, Func<TState, Exception, string> formatter)
{
    var formattedLogValues = state as FormattedLogValues;
    if (formattedLogValues != null)
    {
        foreach (var item in formattedLogValues)
        {
            // Do stuff with item.Key & item.Value
        }
    }
...
}

[jaredcnance]

what's the status of this request? i'd also be happy to work on a PR, based on @roji's suggestions, if the proposal would be accepted. Although, I'm not sure it needs to be a Dictionary, why not just pass params object[] args down to the logger? This would allow things like:

_log.LogInformation("stuff happened", new { clientId } );

and an ILogger may handle that however it chooses

[davidfowl]

Seems like a reasonable request. I like https://github.com/aspnet/Logging/issues/533#issuecomment-285690699 but I think adding extension methods might actually confuse things unless you had to pass this type explicitly. Would something like this be supported?:

C# _log.LogInformation("Something {property}", p1, new { property2 = p2 });

Would the extension method combine the properties in the template with the extra properties passed in?

Just FYI, when you add scopes with properties, loggers are supposed to do the same thing, that is, combine properties from the ambient scope into all existing log messages. Good logger implementations should do this (some of ours don't 😞).

Do you have any thoughts on this @nblumhardt?

/cc @glennc @pakrym

[pakrym]

Having feature is nice but we need a way to do it without allocations.

[davidfowl]

@pakrym suggested we can invent a new syntax for naming the positional arguments without printing them in the log message. This saves the dictionary allocation and allows you to use the precompiled templates.

C# _log.LogInformation("Foo {foo}[bar,baz]", foo, bar, baz);

[jaredcnance]

@davidfowl how does the proposed format differ from:

_log.LogInformation("Foo {foo}{bar}{baz}", foo, bar, baz);

if I understand what you're saying, MessageFormatter would simply ignore the new bracketed tokens? but all of the parameters will still be available in
the FormattedLogValues?

but you're still required to include the parameters in the message. i still think that the decision about what should be done with params object[] args should be delegated to the ILogger implementation. but maybe i'm alone on that.

[nblumhardt]

I think extending the syntax is probably a fresh can of worms :-) .. it would achieve the no-alloc goal, but there's a lot of design space, docs, and integration work lurking there.

(We've pushed back against adding much more to templates than just "named placeholders" because additional syntax will work against discoverability and reliability in the long run. It's tough to remember special-case syntax for just one or two log messages in an app, and likely that syntax mistakes in message templates won't be caught at development time.)

Something like BeginScope() seems like a simpler way to go. I'll propose WithProperty() as a similar API without the ambient state/scope stack involved.

First, to _make additional properties available_ without requiring allocations in the calling code, we could use:

var wp = log.WithProperty("SomeProperty", someValue);
wp.LogInformation("This has the property attached");

Where the value argument is generic T.

Now, if the logger is enabled, this still necessitates an allocation for the return value, but levelling WithProperty() would fix that:

var wp = log.WithProperty(LogLevel.Debug, "SomeProperty", someValue);
// If debug level events aren't enabled, scope == log and no property is attached
wp.LogInformation("This has the property attached only when `Debug` is enabled");

[pakrym]

@nblumhardt it's allocation per property value for loggers that are enabled, a bit too much for a common scenario,

[nblumhardt]

@pakrym fair point 👍

Just so I can understand the cost properly... any formatted event that goes through the pipeline today requires allocations for the state object and the arguments - is the cost here much different?

[akiander]

@roji - a sincere thank you for identifying this issue. I am trying to implement an ILogger and I have this exact problem. I opened up dotnet/extensions#655 for this issue, which can be closed since this issue covers it.

Because the field is private, I had to use reflection to get to the raw values passed to the logger:

var field = typeof(FormattedLogValues).GetRuntimeFields().Where(f => f.IsPrivate && !f.IsStatic && f.Name == "_values").FirstOrDefault();

But that is not an appropriate solution, just a temporary workaround until this issue is solved correctly.

In my opinion, I don't think any syntax change is required here. I think this issue is solved by making the _values field public (readonly):

Microsoft.Extensions.Logging.Internal.FormattedLogValues._values

That way no matter what gets passed, the ILogger can access it.

[muratg]

cc @glennc for his thoughts on this.

[StephenCleary]

@davidfowl

when you add scopes with properties, loggers are supposed to do the same thing, that is, combine properties from the ambient scope into all existing log messages.

Do you mean by this that a log message template can reference parameters defined in its enclosing scopes, or just that the scope can/should be output by the logger? I don't see any loggers doing the former.

[andycmaj]

I wanna jump in here for a sec because i think i might be able to clarify the actual use case the OP was thinking of.

templated message logs are great, but when you're piping your log events to an index like splunk, stackdriver, etc. you really don't need any message at all. When you're trying to consume application logs, i find the context/DATA is the most important thing. I don't care about an actual human-readable message, eg "A thing happened during {step}". In real-world scenarios where developers are looking at tons of log events, they want to be able to data-mine, and thousands of events, all with the same english sentence as a message, are mostly noise.

I think of my log events as events. EventName, Data (and other metadata like Source, Level, etc.).

So the logging API i've wrapped around serilog, which has the same formatted-message API, looks like this:

eventLogger.InfoEvent(string eventName, object eventData);

eventLogger.InfoEvent("ProcessedFoos", new { PropA = "bar", PropB = 42 });

and the events just look like

{
  "EventName": "ProcessedFoos",
  "Level": "Information",
  "Data": {
    "PropA": "bar",
    "PropB": 42
  }
}

So yeah, in production, nobody is looking at the console output of my processes, i'm streaming logs into an index. Once they're there it's kinda pointless to have a "message".

That said, i can certainly see where framework-level logging might want longer messaging that helps the user take actions and diagnose problems. But for application-level logging, i just need to know what happened, what was the context.

So yeah, unique event names and data bags. no human-readable sentences.

[andycmaj]

If anyone is still following this issue, i have a structuredeventlogger library here: https://github.com/andycmaj/SerilogEventLogger. (nuget)

it uses Serilog as a backend and can integrate with native AspNetCore logging via Serilog.AspNetCore

// Redirect framework logging to Serilog logger
services.AddSingleton<ILoggerFactory>(_ => new SerilogLoggerFactory(null, true));

this implements the API i mention in the previous comment.

[yvdh]

Hello,
I second the opinion that what's actually inside the message is unrelated to the structured properties you may want to pass on (I use Graylog2 as a logging backend). Also the mandatory quotes for structured string fields in the messages are rather annoying as they cannot be removed (or can they?).
Yves

[muratg]

@davidfowl please triage or close this one. Thanks.

[ericsampson]

@muratg is this issue related to this one from the old repo?
https://github.com/aspnet/HttpClientFactory/issues/141

At the end of that thread, @glennc mentions the following, and I'm curious where it ended up and if this issue (668) is it?:
"I also think we should put an issue on the backlog about building something that lets you configure what you want to log and log it, it's a feature we've talked about but haven't really started designing or working on."

Thanks!

[muratg]

@ericsampson I don't know.

[viktor-nikolaev]

Hi all,
Is there any decision on this?

I really liked the syntax @davidfowl proposed.
Here is one of my use cases (simplified):

public Task SayHello(string clientInfo)
{
  _logger.LogInformation("SayHello from connection {ConnectionId}", Context.ConnectionId, clientInfo);
  return Task.CompletedTask;
}

clientInfo can be very large and it's not that useful to print it in every log message. However I want to see it in the data bag in elastic.

[arroyc]

I have similar use cases as mentioned by @Veikedo .. would love to know if there is any update on this

[andycmaj]

IMO it's also not useful to see SayHello from connection... in every log message. What you really want to see (and more importantly, track/alert on/graph over time) is the occurrence of { event: 'SaidHello', connection: 'MyConnectionId' }.

[davidfowl]

IMO it's also not useful to see SayHello from connection... in every log message. What you really want to see (and more importantly, track/alert on/graph over time) is the occurrence of { event: 'SaidHello', connection: 'MyConnectionId' }.

You can already log structure, the logger accepts an object. This thread is specifically about text plus other structured data attached to the same log.

This can be implemented today by logging your own objects but you can't use the extension methods in that case. You'd need to create an object that implements IReadOnlyList<KeyValuePair<string, object>> and ToString().

https://github.com/aspnet/AspNetCore/blob/6dc65b16730abb9cba59e759012211e576f99188/src/Hosting/Hosting/src/Internal/HostingRequestFinishedLog.cs#L12

https://github.com/aspnet/AspNetCore/blob/f3f9a1cdbcd06b298035b523732b9f45b1408461/src/Hosting/Hosting/src/Internal/HostingApplicationDiagnostics.cs#L190-L195

This call to log specifies the custom object to log, the formatter callback (how to stringify in case the logger doesn't support structure, like the console logger is textual). All of the right pieces are here to accomplish this today we just need to get more crisp on exactly what people need and why what is currently there today is too difficult.

[andycmaj]

You can already log structure, the logger accepts an object. This thread is specifically about text plus other structured data attached to the same log.

yes that's way i said, "IMO it's also not useful to see '_SayHello from connection..._' in every log message". Meaning I want to log ONLY the structured data and not grammatical strings of text PLUS a json bag.

I think the real ask is that we have an INTERFACE that encourages and supports pure structured event logging. To me, that means EventName: string + Data: KVP essentially. ILogger extensions are an interface that encourages a formatting string and positional arguments. The example you linked to,

   _logger.Log(
                    logLevel: LogLevel.Information,
                    eventId: LoggerEventIds.RequestFinished,
                    state: new HostingRequestFinishedLog(httpContext, elapsed),
                    exception: null,
                    formatter: HostingRequestFinishedLog.Callback);

still requires a formatter and isn't really succinct.

I believe the original ask by @roji was whether a PR would be accepted that would add an interface that looked more like:

eventLogger.InfoEvent(string eventName, object eventData);
eventLogger.InfoEvent("ProcessedFoos", new { PropA = "bar", PropB = 42 });

where the log events just look like

{
  "EventName": "ProcessedFoos",
  "Level": "Information",
  "Data": {
    "PropA": "bar",
    "PropB": 42
  }
}

[davidfowl]

So you're looking for a helper method that does what you can do today to clean up the callsite? That extension method would allocate like crazy (although I'm unsure how you avoid allocations with this design at all).

[andycmaj]

yeah agree... but any structured logging that uses anon objects/kvp lists seems like it would have same problem...

are the allocations for object eventData somehow different than a varargs list of format string replacements?

So you're looking for a helper method

i would probably lean towards a different set of extension methods parallel to LoggerExtensions. maybe IStructuredLoggerExtensions or similar.
I'd still want scopes to continue to work, for example.

[davidfowl]

yeah agree... but any structured logging that uses anon objects/kvp lists seems like it would have same problem...

That signature you have above while convenient is extremely inefficient and wouldn't be something I'd want in the default package:

• It requires reflection to get properties from the anonymous object (which shouldn't be cached)
• Then another object that allocates IKVP needs to be wrapped around that type (it could be a struct though so maybe not the end of the world)
• The object needs to join the event name and the KVPs into a single state object for the ILogger.Log call.

are the allocations for object eventData somehow different than a varargs list of format string replacements?

The default extension methods have several inefficiencies

• They use a params object[] so it always allocates an array if you have a format string, if you don't it's free.
• Being a params object[] means value types are boxed (which results in another allocation)
• Format string need to be parsed on ever call to log (however FormattedLogValues is a struct so it avoids that allocation at least...)

Loggers that implement scopes also need to join the data from the incoming event into and the event itself into an uber collection of properties (more allocations!).

I believe the original ask by @roji was whether a PR would be accepted that would add an interface that looked more like:

Also I'd like to understand a few things:

• What happens to loggers that don't support the logging objects and needs to ToString? Seems like you'd still need a formatter to do something reasonable in this case.
• What does the formatter do for these overloads?
• What happens to exceptions? Do those get appended to the event object as well?
• I see the event object in your sample includes the log level, is that intentional?

Maybe something like this:

```C#
using System;
using System.Collections.Generic;
using Microsoft.Extensions.Logging;

namespace ConsoleApp68
{
class Program
{
static void Main(string[] args)
{
using var loggerFactory = LoggerFactory.Create(builder =>
{
builder.AddConsole();
});

        var logger = loggerFactory.CreateLogger<Program>();

        logger.LogInformation("Hello", new Dictionary<string, object> {
            { "A", 1 }
        });
    }
}

public static class LoggerExtensions
{
    public static void LogInformation<TState>(this ILogger logger, string message, TState state) where TState : IDictionary<string, object>
    {
        state["Message"] = message;
        logger.Log(LogLevel.Information, 0, state, null, (state, exception) => state["Message"].ToString());
    }

    public static void LogInformation<TState>(this ILogger logger, TState state) where TState : IDictionary<string, object>
    {
        logger.Log(LogLevel.Information, 0, state, null, (state, exception) =>
        {
            if (state.TryGetValue("Message", out var value))
            {
                return (string)value;
            }
            return state.ToString();
        });
    }
}

}
```

[jjxtra]

If they added TState overloads for the Information, Warning, etc. extension methods that would help a lot...

[TheXenocide]

We've been migrating from our own logging abstraction to the Microsoft abstraction. We previously implemented our abstraction using NLog (and have tested implementing with ApplicationInsights and verified the same features would be supported with Serilog). We continue to use the NLog implementation of the Microsoft abstraction which is working well for sharing our old analysis tools and we enjoy the flexibility of being able to combine that with console and other loggers (our previous abstraction did not support multiple simultaneous providers, though NLog has support for multiple targets).

Non-message structured data is important to our ability to filter/correlate/analyze/etc. In some cases we use more expensive contextual metadata based on AsyncLocal<T> that travels with the call stack which it seems is similar to BeginScope in some implementations (and which we have been able to replace/integrate with) but much of our metadata is passed directly to the log method as a dictionary; some are easy enough to convert but in some more crucial cases, as well as in some more abstract reusable utilities we have, we have a need to include the metadata without incorporating it into the message string. On top of that we have scenarios where we want to use both message parameters AND the dictionary and it is unclear how we can possibly do this with the existing infrastructure. It looks like the TState approach is more of an either/or scenario where most loggers (at least that matter to us) support the use of a TState that implements IEnumerable<KeyValuePair<string, object>> but then we can't use message parameters in conjunction. Am I also reading above that in some cases keyed-metadata is ignored unless the key is present in the message string? Ideally we would be looking for something that supports both TState AND message parameters; perhaps along the lines of: BeingScope<TState>(this ILogger logger, TState state, string message, params object[] args);, LogError<TState>(this ILogger logger, EventId eventId, Exception exception, TState state, string message, params object[] args), etc. It seems to me like making the FormattedLogValues decorate the state or forcing the state in this case to implement the KVP pattern and concat the values together might be able to make use of the existing allocations/minimize additional impacts, or perhaps an approach that only allocates when the feature is used explicitly which is the developer making a decision to accept the cost in exchange for the benefit.

In the meantime I was thinking maybe we can use a TState of IEnumerable<KeyValuePair<string, object>> manually including the message parameters as their own keys in the state for structured purposes and then just String.Format the values into the message, but then we lose the ability to match on the un-substituted message string which is a handy feature of the message-parameter structured logging approach. This also does not solve our abstract utilities which seek to add metadata to existing message-based logging infrastructure. We really don't want to implement/maintain our own Provider/Factory/Logger, especially when the framework support is so very close to what we (and seemingly many others, especially those using NLog/Serilog/etc.) need and are already used to having in some capacity or another. I'm now taking a look at the above-mentioned LogValuesCollection but this really seems like something that could be done in the framework more effectively/efficiently and to the benefit of more people if it were implemented here.

It's also a little unfortunate that in order to determine what types of structured data were actually supported our only option was to literally dig through source code, both here and in the various repositories of the providers. I understand the flexibility of generic state objects for custom structured logging solutions, but it would be really helpful if there were documentation and possibly suggestions for common best practices to urge some level of common ground between implementations (e.g. suggesting that IEnumerable<KeyValuePair<string, object>> be supported might help future implementations find common ground). I know this is a challenge and that the API is intentionally flexible, just voicing some of the challenges that were non-trivial in our analysis which could be barriers for adopting common practices in other shops.

[TheXenocide]

Ah, it seems that now FormattedLogValues and LogValuesFormatter are internal which means we can't even benefit from the common code for message-based values in home-rolled structured data types that might aim to use both message parameters and additional state. The LogValueCollection mentioned above would have worked for us (though I'd have made a more simple readonly struct based on it), but we're on 3.1 and can no longer do that.

It seems like it would only take a few lines in FormattedLogValues if we constrained the state type for additional parameters to IReadOnlyList<KeyValuePair<string, object>>. An extra constructor parameter, a couple lines to the indexer and an extra + additionalProperties.Count to the Count property? Struct size grows by one pointer no extra allocations (besides whatever the user code does to create their IReadOnlyList).

[TheXenocide]

Here's what we're prototyping with right now.

https://gist.github.com/TheXenocide/f7d8a249ec19857dee926426e2319746

Almost all of it is copy/pasted from this repository with a very small number of changes (we can't wait around for .NET 5 to release). If this (or something similar) seems acceptable I might be able to find some time to put together a pull request. Conceptually we wouldn't need the CustomLogValuesFormatter at all (it's a straight copy/paste + rename) and we could EITHER keep the StructuredAndFormattedLogValues struct and use it from the extension methods which need it OR we could just add the functionality into FormattedLogValues and only have one class. I can see pros/cons to both.

Correct me if I'm wrong, but I believe this still satisfies the "No Additional Allocations" goals exactly as well as the current implementation and allows the consumer user to supply an existing Dictionary (which we already have several of in our utilities) or a custom class/struct like the above noted HostingRequestFinishedLog. I had considered allowing it to receive IEnumerable or IReadOnlyList making it either a little more or less flexible but I think this gives a happy middle ground that doesn't require existing dictionaries to be pushed through ToList, etc.

[gitfool]

We also need this! Using Serilog behind the scenes _but_ using ILogger abstraction in libraries and elsewhere to be a good citizen and logger agnostic. Lowest common denominator sucks. 😞

@TheXenocide please at least try to push for this to be incorporated into .NET 5! 🍺

Meanwhile, I might take your gist and run with it.

[snakefoot]

Since you can provide whatever LogState-objects you like, then it is just a matter a providing one that supports additional properties.

• Simple Approach

• Advanced Approach - With message template parsing.

One can sprinkle some ILogger-extension methods around, and then you have what you need.

P.S. Both Serilog and NLog should have no issues with capturing additional properties injected by these two approaches (Important part is that LogState implements IEnumerable<KeyValuePair<string, object>>)

[viktor-nikolaev]

Just created a nugget package for it, should work with NLogger and Serilog.
https://www.nuget.org/packages/XeonApps.Extensions.Logging.WithProperty/

usage:

  // inline
  logger
    .WithProperty("SomeProp", "value")
    .LogInformation("User {User} logged in", "Jon");

  // reassign a logger with props
  logger = logger
    .WithProperty("OneProp", 22)
    .WithProperty("End", 21)
    .WithProperties(
      ("key", "value")
    )
    .WithProperties(
      new KeyValuePair<string, object>("another", "one"),
      new KeyValuePair<string, object>("some", "more"),
      new KeyValuePair<string, object>("End", "more")
    );

  // will have all the added props as well as props from the template 
  logger.LogInformation("Event {Event} happened", "UserLoggedOut");

[TheXenocide]

Since you can provide whatever LogState-objects you like, then it is just a matter a providing one that supports additional properties.
[...]
One can sprinkle some ILogger-extension methods around, and then you have what you need.

@snakefoot I think the main difference between the techniques mentioned in your links and a lot of the desire I'm seeing here would be the ability to use both the structured template text AND additional structured properties not included in the message together. The examples you linked manage to accomplish logging a structured object which can be turned into a string message, but it doesn't get to leverage the structured template text, thus forcing the user to reinvent the wheel.

I think @viktor-nikolaev manages to accomplish this, though the approach feels a bit more allocation heavy (the example above creates 5 new instances of ILogger to log two messages, though admittedly that's just a verbose sample and it could create 1 new logger per message just fine, which isn't as bad, plus reuse of some properties but not others seems like a viable use of the alternative pattern he provides).

It feels like it would be relatively trivial to modify the provided implementation, and rather non-trivial (and entirely too intimately familiar with the inner workings of the logging abstractions provided here) to provide our own implementation (which also is unable to make any practical reuse of the templating mechanism built-in to the abstraction library, at present). Keeping the standard practice for the structured template strings is really important to us because it is both easy to read and readily referenced all over the internet, rather than us concocting some home-rolled similar-but-different solution everyone will have to relearn and for which there will be few examples of in the wild.

[snakefoot]

@TheXenocide Have you tried Advanced Approach - With message template parsing ? (It does both)

[Dotnet-GitSync-Bot]

I couldn't figure out the best area label to add to this issue. Please help me learn by adding exactly one area label.

[dmitry-84]

It will be useful if FormattedLogValues._values be exposed. For example with key named {OriginalValues} in KeyValuePair<string, object> similarly as it was done for _originalMessage/{OriginalFormat}