Structured Logging Parameter Not Logged If Not Explicitly Referenced In Message

[suntereo]

Hello,

Thank you for your package! :)

I have been using NLog.Loki and encountered an issue related to structured logging.

In a scenario where I explicitly reference the structured logging parameter in my log message string, everything works as expected:

NLog.LogManager.GetCurrentClassLogger().Error("My test message 1|{data}", new
{
    SomeProperty = "Test",
    AnotherProperty = "Other details here"
});

In the above case, both the log message and the structured data are correctly sent to Loki.

However, if I attempt to log a message without specifying the {data} placeholder in the message string, but continue to pass an object as the second argument, the structured data does not appear in Loki:

NLog.LogManager.GetCurrentClassLogger().Error("My test message 2", new
{
    SomeProperty = "Test",
    AnotherProperty = "Other details here"
});

In this instance, the log message is sent to Loki, but the structured data is not included.

This behavior is inconsistent with other logging systems like Graylog, where structured data is logged even if it is not explicitly referenced in the log message.

I'm trying to understand if this is a design decision or an oversight. We are in the process of transitioning from Graylog to Loki, and this issue poses a significant challenge as we have numerous existing lines of code following the second format. We are worried that we might miss updating some lines and hence lose visibility into valuable logging data.

Could you please clarify this behavior and suggest how we might address this issue? If it's a bug, could it be fixed in a future release?

Thanks for your help!

[snakefoot]

NLog only capture parameters as named-properties, when using the message-template-syntax.

You can consider doing this:

NLog.LogManager.GetCurrentClassLogger().WithProperty("SomeProperty", "Test").Error("My test message 2");

Or doing this:

NLog.LogManager.GetCurrentClassLogger().ForErrorEvent().Property("SomeProperty", "Test").Message("My test message 2").Log();

See also: https://github.com/NLog/NLog/wiki/How-to-use-structured-logging

[suntereo]

I've looked into the behavior I described in more detail, and I've found that it is indeed working as I described with the NLog.Web.AspNetCore.Targets.Gelf package for writing to Graylog.

That package includes a sendLastFormatParameter setting, which is explained in their documentation as: "sendLastFormatParameter: default false. If true, the last parameter of the message format will be sent to Graylog as a separate field per property."

They give the following example in their documentation to illustrate this feature:

Logger.Info(comic.Title, new { Publisher = comic.Publisher, ReleaseDate = comic.ReleaseDate });

So even though the parameter is not named in the message, it will still log Publisher and ReleaseDate as separate fields in Graylog.

Here's how they handle this in their code (source):

protected override void Write(LogEventInfo logEvent)
{
    foreach (var par in this.Parameters)
    {
        if (!logEvent.Properties.ContainsKey(par.Name))
        {
            string stringValue = par.Layout.Render(logEvent);
            logEvent.Properties.Add(par.Name, stringValue);
        }
    }

    if (SendLastFormatParameter && logEvent.Parameters != null && logEvent.Parameters.Any())
    {
        // handled here
        logEvent.Properties.Add(ConverterConstants.PromoteObjectPropertiesMarker, logEvent.Parameters.Last());
    }

    var jsonObject = Converter.GetGelfJson(logEvent, Facility, GelfVersion);
    if (jsonObject == null) return;

    _lazyITransport.Value.Send(_lazyIpEndoint.Value, jsonObject.ToString(Formatting.None, null));
}

I'm wondering if you would consider implementing a similar feature in your package, allowing structured data to be logged in Loki without explicit reference in the log message. This would greatly help our transition from Graylog to Loki.

Thank you for considering this request!

[corentinaltepe]

Hi, thank you both for the detailed information. Sorry for my late reply.

I wouldn't mind adding a sendLastFormatParameter feature. I think the feature should be off/false by default, given this is not the expected behavior by most NLog users, and this would be consistent with NLog.Web.AspNetCore.Targets.Gelf default configuration.

[corentinaltepe]

I reproduced the problem you described in this line of code in the template project, where I placed two event properties but referenced only one property in the message template. And we can see that only the referenced property is rendered in the message sent to Loki.

[suntereo]

Thank you for considering the addition of a sendLastFormatParameter feature. It's helpful to know you're receptive to suggestions that could improve the package.

While I would love to contribute, my capacity is currently limited, and it might take me a significant amount of time to familiarize myself with the codebase and make this update. As you have a deeper understanding of the package, would it be possible for you or your team to take this on?

If so, would you have an approximate timeline for this feature?

Thanks again for your support!

[corentinaltepe]

I can't really say when I'd implement the feature. It won't be this weekend, it might be next weekend, but not sure.

The code base is luckily very small. There's a template project, a simple console app using the library, and a docker-compose to spin up loki and Grafana, in case you want to give it a try and test it out.

Since you already highlighted the implementation in Gelf target, you should be comfortable with Loki target. I believe the code should be placed in the LokiTarget class, likely in this method: https://github.com/corentinaltepe/nlog.loki/blob/1c007afa9184945e210e2155e24c05562601fe52/src/NLog.Loki/LokiTarget.cs#L80C58-L80C58

[suntereo]

Ok, great! I will see if my project manager will give me any time to look into next week. Thanks again!

[suntereo]

Hi! I created a PR for this at https://github.com/corentinaltepe/nlog.loki/pull/88

It goes beyond the discussion above and also handles creating fields from the event properties, if they exist. This also makes it more like the Graylog target. Thanks for your consideration!

[corentinaltepe]

Hi. Thank you very much for the feature!

I realize that the second feature you mentionned actually creates one Loki label per event property. This can become a massive issue, since it goes againt Loki's best practices. I had initially refused to implement such feature in #75 to avoid issues to users. However since you're the second person to request it, and you provided the implementation, I made it available behind a feature flag, and with clear warnings against it in the Readme.

In order to use the feature, you'll need to enable both feature flags eventPropertiesAsLabels and sendLastFormatParameter.

Again, this may become a problem in your Loki instance, depending on the quantity of streams you will generate. Consider using JsonLayout, although right now you can't sendLastFormatParameter that way.

This is now available in v2.1.0 https://github.com/corentinaltepe/nlog.loki/releases/tag/2.1.0

[suntereo]

Hi @corentinaltepe,

I must admit, my lack of familiarity with Loki's best practices led me to create this PR. I proposed changes that I now regret. You mentioned the potential performance implications, and I now see their significance.

I have also found a serious bug with sendLastFormatParameter when mixing named parameters. The new changes are causing log entries to fail and this obviously is a concern. Because of these issues, I won't be using the new feature.

Your collaboration has been exceptional, and I appreciate the time and effort you've invested. However, given the known performance concerns and the newly discovered bug, it may be prudent to reconsider the inclusion of this feature.

While I'm deeply grateful for your willingness to work with me, I feel it's my responsibility to emphasize these concerns. Thank you once again for your understanding, and I look forward to continuing to engage with your package!

[corentinaltepe]

Hi @suntereo,

Thank you very much for your feedback. At least we tried. I understand the need to structure log parameters even though they're not referenced by the message template. This is the behavior of Javascript's console.log(), and I believe I have used it with Serilog as well. Our mistake was probably to try and force the feature into a target library, going against a design decision of the core library.

I will remove the feature sendLastFormatParameter to avoid other users getting the bug you mention. I really appreciated working with you.