opentelemetry-dotnet icon indicating copy to clipboard operation
opentelemetry-dotnet copied to clipboard

Invalid Characters in "{OriginalFormat}" when using OTLPExporter

Open bhnaphade opened this issue 1 year ago • 1 comments

Package

OpenTelemetry.Exporter.OpenTelemetryProtocol

Package Version

Package Name Version
OpenTelemetry.Api 1.9.0
OpenTelemetry 1.9.0
TBD TBD

Runtime Version

net8.0

Description

We have encountered with the IncludeFormattedMessage setting in our OpenTelemetry .NET setup. When this setting is configured as false, the {OriginalFormat} field is not emitted, but the body remains unresolved. Conversely, when the setting is true, the {OriginalFormat} field is emitted, and the body is resolved. Unfortunately, our backend treats the {} characters as invalid, causing processing issues.

Here are sample log records for reference:

When IncludeFormattedMessage is set to false:

{ "body": "Food {name} price changed to {price}", "traceid": "trace-id-1", "spanid": "span-id-1", "severity": "Information", "attributes": { "name": "artichoke", "price": "9.99", "logrecord.event.id": 123456789, "logrecord.event.name": "PriceChange", "value": [ "[EventId, event-id-1]", "[EventType, event-type-1]", "[SourceNode, source-node-1]", "[SourceName, Internal]", "[Time, 08/06/2024 16:23:21]", "[ReceiveTime, 08/06/2024 16:23:21]", "[LocalTime, (null)]", "[Message, Price Changed]", "[Severity, 500]" ] }, "resources": { "service.instance.id": "instance-id-1", "service.name": "service-name-1", "service.namespace": "service-namespace-1", "service.version": "service-version-1", "telemetry.sdk.language": "dotnet", "telemetry.sdk.name": "opentelemetry", "telemetry.sdk.version": "1.9.0" }, "instrumentation_scope": { "name": "instrumentation-scope-name-1" } } When IncludeFormattedMessage is set to true:

{ "body": "Food artichoke price changed to 9.99", "traceid": "trace-id-2", "spanid": "span-id-2", "severity": "Information", "flags": 1, "attributes": { "name": "artichoke", "price": "9.99", "logrecord.event.id": 987654321, "logrecord.event.name": "PriceChange", "{OriginalFormat}": "Food {name} price changed to {price}" }, "resources": { "service.instance.id": "instance-id-2", "service.name": "service-name-2", "service.namespace": "service-namespace-2", "service.version": "service-version-2", "telemetry.sdk.language": "dotnet", "telemetry.sdk.name": "opentelemetry", "telemetry.sdk.version": "1.9.0" }, "instrumentation_scope": { "name": "instrumentation-scope-name-2" } }

Please help with a fix that allows us to resolve the body without emitting the {OriginalFormat} field. Alternatively, consider changing {OriginalFormat} to OriginalFormat in the OTLP stack similar to how its handled in the ConsoleLogRecordExporter

Steps to Reproduce

var loggerFactory = LoggerFactory.Create(builder => { builder.AddOpenTelemetry(logging => { logging.IncludeScopes = true; logging.IncludeFormattedMessage = true; logging.SetResourceBuilder(ResourceBuilder.CreateDefault().AddService( serviceName: "MyService", serviceVersion: "1.0.0")); logging.AddConsoleExporter(); }); });

Expected Result

{ "body": "Food artichoke price changed to 9.99", "traceid": "trace-id-2", "spanid": "span-id-2", "severity": "Information", "flags": 1, "attributes": { "name": "artichoke", "price": "9.99", "logrecord.event.id": 987654321, "logrecord.event.name": "PriceChange", "OriginalFormat": "Food {name} price changed to {price}" }, "resources": { "service.instance.id": "instance-id-2", "service.name": "service-name-2", "service.namespace": "service-namespace-2", "service.version": "service-version-2", "telemetry.sdk.language": "dotnet", "telemetry.sdk.name": "opentelemetry", "telemetry.sdk.version": "1.9.0" }, "instrumentation_scope": { "name": "instrumentation-scope-name-2" } }

Actual Result

{ "body": "Food artichoke price changed to 9.99", "traceid": "trace-id-2", "spanid": "span-id-2", "severity": "Information", "flags": 1, "attributes": { "name": "artichoke", "price": "9.99", "logrecord.event.id": 987654321, "logrecord.event.name": "PriceChange", "{OriginalFormat}": "Food {name} price changed to {price}" }, "resources": { "service.instance.id": "instance-id-2", "service.name": "service-name-2", "service.namespace": "service-namespace-2", "service.version": "service-version-2", "telemetry.sdk.language": "dotnet", "telemetry.sdk.name": "opentelemetry", "telemetry.sdk.version": "1.9.0" }, "instrumentation_scope": { "name": "instrumentation-scope-name-2" } }

Additional Context

No response

bhnaphade avatar Aug 06 '24 22:08 bhnaphade

For better or worse, this is working as designed 🤣 We couldn't change it now without likely breaking users. We could introduce some settings/options to opt-into different behavior though.

I chatted offline with the user(s) and recommended to them as a workaround they investigate a custom processor to remove the {OriginalFormat} attribute and then add it back in with a different key.

More details...

The OtlpLogExporter will always emit a body:

  • When IncludeFormattedMessage == true body will be the formatted message and {OriginalFormat} is dropped (if found). Personally I don't think this is a great design. Perhaps it would have been better to always set body to the template (if we have one) and then put the formatted message into some other attribute. The spec has this log.record.original (experimental) maybe that would work.

  • When IncludeFormattedMessage == false body will be {OriginalFormat} if it was found otherwise it will be either the result of the formatter (if a formatter was provided) else ToString of the TSTate passed to ILogger.Log.

We recommend keeping IncludeFormattedMessage false because formatting the string is expensive to do in the process and backends can do it lazily on demand from the message template if users really want to see it.

As far as adding options to change the behavior I think we should keep this open to gauge the demand and go from there.

CodeBlanch avatar Aug 15 '24 17:08 CodeBlanch