Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

OTLP Logs - remove depth from scope fields #3843

Merged
merged 6 commits into from
Oct 31, 2022
Merged

OTLP Logs - remove depth from scope fields #3843

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
6 commits
Select commit Hold shift + click to select a range
09f1c5c
OTLP Logs - remove depth from scope fields
cijothomas Oct 29, 2022
49787e1
add notes
cijothomas Oct 29, 2022
dfe3694
fix example
cijothomas Oct 29, 2022
bf8abc8
better wording
cijothomas Oct 31, 2022
a95575a
remove few warnings
cijothomas Oct 31, 2022
9e40df7
Merge branch 'main' into cijothomas/otlp-log-scope-fix
cijothomas Oct 31, 2022
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
4 changes: 4 additions & 0 deletions .vscode/settings.json
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -9,10 +9,13 @@
"contoso",
"cref",
"grafana",
"ilogger",
"inheritdoc",
"janotti",
"kanzhelev",
"langword",
"liudmila",
"loglevel",
"mikel",
"molkova",
"monocytogenes",
Expand Down Expand Up @@ -42,6 +45,7 @@
"Tracestate",
"triager",
"typeparam",
"ulong",
"umesan",
"unencrypted",
"unvalidated",
Expand Down
4 changes: 2 additions & 2 deletions examples/Console/TestLogs.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -90,8 +90,8 @@ internal static object Run(LogsOptions options)
});

var logger = loggerFactory.CreateLogger<Program>();
using (logger.BeginScope("My scope 1 with {food} and {color}", "apple", "green"))
using (logger.BeginScope("My scope 2 with {food} and {color}", "banana", "yellow"))
using (logger.BeginScope("{city}", "Seattle"))
using (logger.BeginScope("{storeType}", "Physical"))
{
logger.LogInformation("Hello from {name} {price}.", "tomato", 2.99);
}
Expand Down
5 changes: 5 additions & 0 deletions src/OpenTelemetry.Exporter.OpenTelemetryProtocol/CHANGELOG.md
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -2,6 +2,11 @@

## Unreleased

* Log Exporter modified to no longer prefix scope-depth when exporting ILogger
scopes as attributes. Empty keys and {OriginalFormat} key will be ignored from
scopes.
Comment on lines +5 to +7
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I'm not opposed to this change, but can you give a little more background on why we're making this change?

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Main motivation is the duplication/de-duplication cost, and undesired modification of user attributes.
Explanation for each of the case:

  1. With plain string, the key is null/empty, which is unallowed in OTel. But even if we were to use some magic key like "scope", it'll be duplicated, when user have nested scopes. The .NET official docs are being fixed already to no longer showing scopes with strings.

  2. With {OriginalFormat} - this is an unintentional side effect in Ms.Ext.Logging. It makes sense for Log message, where there is a Format() function, which can be used to get the fully formatted string. There is nothing like that for Scopes. "{OriginalFormat}" key will be duplicated if user has nested scopes, and we do not want to pay for dedup efforts.

The current approach simply prefixed a numeric value (based on scope depth), to solve this problem. But overriding user provide attributes with something else is undesirable (and affects perf too).

The following example can show why this is bad:

using (logger.BeginScope(new List<KeyValuePair<string, object>>
{
new KeyValuePair<string, object>("userid", "cijo")
}))
using (logger.BeginScope(new List<KeyValuePair<string, object>>
{
new KeyValuePair<string, object>("transactionid", "abcd")
}))
{
logger.LogInformation("Hello from {food} {price}.", "artichoke", 3.99);
}

the above would have resulted in attributes ("[0]:userid", "cijo"), ("[1]:transactionid", "abcd") as per current code, instead of ("userid", "cijo"). ("transactionid", "abcd"), per this PR.

([3843](https://github.com/open-telemetry/opentelemetry-dotnet/pull/3843))

## 1.4.0-beta.2

Released 2022-Oct-17
Expand Down
35 changes: 29 additions & 6 deletions src/OpenTelemetry.Exporter.OpenTelemetryProtocol/Implementation/LogRecordExtensions.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -78,7 +78,8 @@ internal static OtlpLogs.LogRecord ToOtlpLog(this LogRecord logRecord, SdkLimitO
var attributeValueLengthLimit = sdkLimitOptions.AttributeValueLengthLimit;
var attributeCountLimit = sdkLimitOptions.AttributeCountLimit ?? int.MaxValue;

// First add the generic attributes like category, eventid and exception, so they are less likely being dropped because of AttributeCountLimit
// First add the generic attributes like Category, EventId and Exception,
// so they are less likely being dropped because of AttributeCountLimit.

if (!string.IsNullOrEmpty(logRecord.CategoryName))
{
Expand Down Expand Up @@ -145,18 +146,40 @@ internal static OtlpLogs.LogRecord ToOtlpLog(this LogRecord logRecord, SdkLimitO
otlpLogRecord.Flags = (uint)logRecord.TraceFlags;
}

int scopeDepth = -1;
logRecord.ForEachScope(ProcessScope, otlpLogRecord);

void ProcessScope(LogRecordScope scope, OtlpLogs.LogRecord otlpLog)
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

nit:

  • This can be made static void ProcessScope(LogRecordScope scope, OtlpLogs.LogRecord otlpLog) now that it isn't using a closure. On newer runtimes the delegate will be created the first time it is accessed and then reused.

  • For best perf, make a static field for the delegate and pass it in to logRecord.ForEachScope. That will ensure for all runtimes it is reused and doesn't need an existence check.

{
scopeDepth++;
foreach (var scopeItem in scope)
{
var scopeItemWithDepthInfo = new KeyValuePair<string, object>($"[Scope.{scopeDepth}]:{scopeItem.Key}", scopeItem.Value);
if (OtlpKeyValueTransformer.Instance.TryTransformTag(scopeItemWithDepthInfo, out var result, attributeValueLengthLimit))
if (scopeItem.Key.Equals("{OriginalFormat}") || string.IsNullOrEmpty(scopeItem.Key))
{
otlpLog.AddAttribute(result, attributeCountLimit);
// Ignore if the scope key is empty.
// Ignore if the scope key is {OriginalFormat}
// Attributes should not contain duplicates,
// and it is expensive to de-dup, so this
// exporter is going to pass the scope items as is.
// {OriginalFormat} is going to be the key
// if one uses formatted string for scopes
// and if there are nested scopes, this is
// guaranteed to create duplicate keys.
// Similar for empty keys, which is what the
// key is going to be if user simply
// passes a string as scope.
// To summarize this exporter only allows
// IReadOnlyList<KeyValuePair<string, object?>>
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Just mention IEnumerable<KeyValuePair<string, object?>>?

IReadOnlyList<KeyValuePair<string, object?>> implements IEnumerable<KeyValuePair<string, object?>> anyway.

// or IEnumerable<KeyValuePair<string, object?>>.
// and expect users to provide unique keys.
// Note: It is possible that we allow users
// to override this exporter feature. So not blocking
// empty/{OriginalFormat} in the SDK itself.
Comment on lines +173 to +175
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Are you suggesting that in the future we might add an exporter option to override this behavior?

My preference would be to try and avoid this solution if it becomes a need in the future. Given we have ILogger specific notions into our LogRecord data model we're required to handle them somehow in our exporters. But, I'd prefer to avoid spilling ILogger specific notions into our OTLP exporter options.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

deduping is not going to be Ilogger specific. It'll be same for any source which itself prevent duplicates.
For Activity, we do not produce duplicates, so if we want to have that similar behavior, we need to expose something.
(but it could be in the SDK or Exporter...)

}
else
{
if (OtlpKeyValueTransformer.Instance.TryTransformTag(scopeItem, out var result, attributeValueLengthLimit))
Comment on lines +177 to +179
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

nit: Looks like you could combine these into a single else if

{
otlpLog.AddAttribute(result, attributeCountLimit);
}
}
}
}
Expand Down