Logs exporter: {OriginalFormat} should be exported as message_template.text

[nblumhardt]

Feature request

The .NET Logs exporter includes the log event's message template in the oddly-named {OriginalFormat} field.

E.g. when IncludeFormattedMessage = true, sending an event with:

_logger.LogInformation("Hello, {name}", "world");

results in a LogRecord with an attribute named "{OriginalFormat}", and value "Hello, {name}".

It's great (crucial) having this data attached to the log record, but the name is inappropriate and awkward.

Ideally, since the value is a message template, it would be called something like message_template.text or a similarly descriptive name.

Alternatives

A simple name like message_template would also work, but makes implementation of additional message template-derived attributes harder to name. Using the .text suffix leaves the path clear for other attributes to be included under message_template.*.

Additional Context

Message templates were originally implemented by Serilog, were inherited by MEL, and are now supported across a number of different libraries and ecosystems including all of the .NET logging libraries currently in wide use.

Using a standard attribute name for the message template will collectively benefit all consumers that use it. The Serilog OTLP implementation is intending to use the attribute message_template.text.

[cijothomas]

Agree about the awkward name {OriginalFormat}.
We indeed treat it as special (https://github.com/open-telemetry/opentelemetry-dotnet/blob/main/src/OpenTelemetry.Exporter.OpenTelemetryProtocol/Implementation/LogRecordExtensions.cs#L120-L125) by using it to populate the Body. This won't work if you IncludeFormattedMessage=true;

There is some wip (#4334) which would be relevant to this as well.

[CodeBlanch]

I think if the goal is to define a "standard" spot for message template(s) we should approach this through the OpenTelemetry Specification.

/cc @alanwest

[nblumhardt]

That sounds great; thank you both for taking a look 👍

I can't add much to the discussion at this point, but if you're able to loop me in or link to spec discussions here I'd love to follow along.

[nblumhardt]

treat it as special ... by using it to populate the Body.

@cijothomas in that default mode, is there any way for consuming tools to detect that the body is a template (vs the fully-rendered message)? Knowing that the body is a template opens up the possibility of rendering on demand, for example when the event is viewed by a human user.

Here's how that kind of thing looks in Seq, for example:

(The screenshot's using the IncludeFormattedMessage mode, and pulling the template from {OriginalFormat} :-) )

[cijothomas]

is there any way for consuming tools to detect that the body is a template

Looking for the placeholders (curly braces) would be the way to go, as there is no other indication if body is formatted one or the template itself. Some tools like AzureDataExplorer has (experimental) support for filling in the placeholders from attributes.

[nblumhardt]

Nice! Sounds like a reliable (non-heuristic) method of determining that the body is a template could also benefit them? (Do you know if anyone involved with it is reachable here?)

[cijothomas]

https://github.com/open-telemetry/opentelemetry-dotnet/pull/4334/files#diff-e28eaa16d5ac47130740a2783c474f316e9a1699aa3ada3a537951246e7cf517L123 This PR keeps the same behavior. So if you do IncludeFormattedMessage = true, then one of the attributes could be "{OriginalFormat}".

[cijothomas]

Nice! Sounds like a reliable (non-heuristic) method of determining that the body is a template could also benefit them? (Do you know if anyone involved with it is reachable here?)

I do not think so. The Azure Data Explorer is not an OSS product, so I can't just point to source code of it handling the messagetemplate replacement!

https://messagetemplates.org/ - Do check this out, as it may have some leads.

[nblumhardt]

Thanks for your reply! Sorry, I was unclear - I didn't mean that ADX might have a non-heuristic method of detecting message templates, but rather that the product team would be interested in gaining one, i.e. via one of the mechanisms we're discussing.

Detecting message templates heuristically is possible, but there's a computational cost and false-positive rate that would be avoided with a standardized attribute name (or other marker, in the case that the template is in Body).

[rpanand24]

Currently with IncludeFormattedMessage set to true, the data is duplicated in FormattedMessage, Body and in Attributes.

it would be nice to have the FormattedMessage as default in Body and provide a setting to include the template (IncludeTemplate or something else) instead. may be in message_template.text or body.template.

When we use APM tools like Elastic Cloud, Splunk Observability etc., We would like to optimise the cost of log data storage. reducing these duplicates will be much helpful.

LogRecord.Severity:                Info
LogRecord.SeverityText:            Information
LogRecord.FormattedMessage:        Lorem ipsum dolor sit amet, consectetur adipiscing elit.Pellentesque porta, ligula vel hendrerit efficitur, lorem sem accumsan lectus, at accumsan diam ligula sit amet ligula. Aenean pellentesque blandit ex, in porta massa consectetur in. Aenean fermentum lacus in ipsum congue, at eleifend eros scelerisque. Proin sit amet ex ullamcorper, aliquet ipsum eget, vestibulum ex. Aliquam in lacus vitae augue auctor rutrum vitae a ipsum. Aenean libero felis, eleifend non turpis non, ultricies tristique sapien. Vivamus ac venenatis tortor.
LogRecord.Body:                    Lorem ipsum dolor sit amet, consectetur adipiscing elit.Pellentesque porta, ligula vel hendrerit efficitur, lorem sem accumsan lectus, at accumsan diam ligula sit amet ligula. Aenean pellentesque blandit ex, in porta massa consectetur in. Aenean fermentum lacus in ipsum congue, at eleifend eros scelerisque. Proin sit amet ex ullamcorper, aliquet ipsum eget, vestibulum ex. Aliquam in lacus vitae augue auctor rutrum vitae a ipsum. Aenean libero felis, eleifend non turpis non, ultricies tristique sapien. Vivamus ac venenatis tortor.
LogRecord.Attributes (Key:Value):
    OriginalFormat (a.k.a Body): Lorem ipsum dolor sit amet, consectetur adipiscing elit.Pellentesque porta, ligula vel hendrerit efficitur, lorem sem accumsan lectus, at accumsan diam ligula sit amet ligula. Aenean pellentesque blandit ex, in porta massa consectetur in. Aenean fermentum lacus in ipsum congue, at eleifend eros scelerisque. Proin sit amet ex ullamcorper, aliquet ipsum eget, vestibulum ex. Aliquam in lacus vitae augue auctor rutrum vitae a ipsum. Aenean libero felis, eleifend non turpis non, ultricies tristique sapien. Vivamus ac venenatis tortor.

Resource associated with LogRecord:
telemetry.sdk.name: opentelemetry
telemetry.sdk.language: dotnet
telemetry.sdk.version: 1.8.0
service.name: unknown_service:otel-dotnet

[cijothomas]

@rpanand24 Are you seeing duplicate information when using OTLP Exporter? The above seems to be the output of console exporter, and might not reflect what actually gets send to APM backends, when using OTLP Exporter!

[robertcoltheart]

Is there a consensus for what to do with this issue? I'm happy to submit a PR to address this.

For reference, we are using Serilog + OpenTelemetry (with IncludeFormattedMessage=true) and this is the output I see in Loki:

{
  "body": "HTTP \"GET\" \"/api/v1/logging\" responded 200 in 39.9625 ms",
  "traceid": "cc9da936753e8b271d7934cd51c4622b",
  "spanid": "a2a7f0304b6860e3",
  "severity": "Information",
  "flags": 1,
  "attributes": {
    "Elapsed": 39.9625,
    "RequestMethod": "GET",
    "RequestPath": "/api/v1/logging",
    "SourceContext": "Serilog.AspNetCore.RequestLoggingMiddleware",
    "StatusCode": 200,
    "{OriginalFormat}": "HTTP {RequestMethod} {RequestPath} responded {StatusCode} in {Elapsed:0.0000} ms"
  },
  "resources": {
    "host.name": "AP-wGV6SeqXrNMH",
    "service.instance.id": "35cd735f-5e1f-4406-ad4a-1033a53ea641",
    "service.namespace": "My.AspNet.Service",
    "service.version": "1.0.0",
    "telemetry.sdk.language": "dotnet",
    "telemetry.sdk.name": "opentelemetry",
    "telemetry.sdk.version": "1.8.0"
  },
  "instrumentation_scope": {
    "name": "Serilog.AspNetCore.RequestLoggingMiddleware"
  }
}

[github-actions]

This issue was marked stale due to lack of activity and will be closed in 7 days. Commenting will instruct the bot to automatically remove the label. This bot runs once per day.

[nblumhardt]

This still seems like a gap worth closing; {OriginalFormat} is weird baggage for us all to carry along indefinitely :-)