[sdk.logging] More consistent handling of StateValues/Attributes

[CodeBlanch]

[This work was originally done as part of 1.4 dev but got moved to main-logs branch with the other things waiting for the spec to go stable. I think this is safe to go in for 1.5 so opening this to get feedback.]

Background

• Originally we just had LogRecord.State but that is just an object. Pushes all the complexity onto exporters to figure out what to do. Later on we realized the state isn't really safe to use in batching. The state is only good during the "Log" call lifecycle.

• Later we added StateValues which is IReadOnlyList<KeyValuePair<string, object?>> a more friendly thing for exporters to deal with. But a mistake was likely made here. We only set that if OpenTelemetryLoggerOptions.ParseStateValues is set to true (it is false by default). That was done because the thinking was parsing the state would be expensive. As it turns out, most state is just castable. It is a cheap thing for the most part. Some exporters have done weird things like turn this on automatically.

Goals

• Primarily this PR is seeking to smooth out the experience for users. When it is cheap, we should just expose the IReadOnlyList<KeyValuePair<string, object?>> automatically. State isn't safe so we should obsolete it.

• Some of the names are very different from what the spec (LogModel) has. Trying to make it a bit closer. This will make things more cohesive with the upcoming bridge api as well.

• We only have FormattedMessage which may be null. There is no concept of Body (could be template or formatted message). It should be more consistent. You should always get something to log. Either template, template & formatted message (depending on settings), or a formatted message. This also sets up the upcoming bridge api as well where Body can be passed directly.

Changes

• Marks LogRecord.State as obsolete. State really isn't safe to use outside of the frame where the log is written.

• Adds LogRecord.Body which is now set automatically to {OriginalFormat} if it is found as the last tag on state. If it isn't found we automatically call the formatter (regardless of IncludeFormattedMessage) and use the FormattedMessage value as Body. If there is no formatter we call ToString() on the state. The idea here is you should always get something to log. A log with no message is kind of silly?

• Adds LogRecord.Attributes and obsoletes LogRecord.StateValues. Really no reason for this other than it makes LogRecord a little closer to the spec.

• Redefines ParseStateValues. If state is IReadOnlyList<KeyValuePair<string, object?>> or IEnumerable<KeyValuePair<string, object?>> than Attributes \ StateValues will exist automatically. If state is some random unknown object (which should be rare)...

  • If ParseStateValues is false: Attributes \ StateValues will be null.
  • If ParseStateValues is true: We actually generate Attributes \ StateValues for the object's top-level public properties using reflection. This is expensive, so it is still false by default.

• If users really don't want state/attributes at all (perhaps they just want formatted message) a new option IncludeAttributes (default true) is available. Note: The option was made internal during review of this PR.

• A new option IncludeTraceState has been added, defaulted to false. TraceState isn't on LogModel. It is dropped by Otlp for example. Made it optional so we don't waste cycles on it. Note: The option was made internal during review of this PR.

Public API changes

namespace OpenTelemetry.Logs
{
   public class LogRecord
   {
+     public IReadOnlyList<KeyValuePair<string, object?>>? Attributes { get; set; }
+     public string? Body { get; set; }

+     [Obsolete]
      public object? State { get; set; }
+     [Obsolete]
      public IReadOnlyList<KeyValuePair<string, object?>>? StateValues { get; set; }
   }

   public class OpenTelemetryLoggerOptions
   {
      // Note: These were made internal during review of this PR.
      // Please comment on this PR if these would be useful to you.
+     internal bool IncludeAttributes { get; set; }
+     internal bool IncludeTraceState { get; set; }
   }
}

Merge requirement checklist

• CONTRIBUTING guidelines followed (nullable enabled, static analysis, etc.)
• Unit tests added/updated
• Appropriate CHANGELOG.md files updated for non-trivial changes
• Changes in public API reviewed (if applicable)

[alanwest]

Not excited about this new option. Is the cost of keeping things as is pretty high? In a lot of cases I think TraceState is null or empty anyways.

[CodeBlanch]

I'm not passionate that we absolutely need this. What the Activity.TraceStateString getter does is walk the chain and look for a value. So if you happen to be logging inside of a deeply nested span those cycles get spent even if trace state isn't being used. The idea here was to not spend any time on it unless it was needed.

[utpilla]

I think we should not add this option unless we get perf complaints for this as the use-case it's trying to optimize seems like a rare occurrence.

[CodeBlanch]

Is it rare though? Using TraceState is probably rare. But whether or not it is used doesn't change the perf hit we take to access it! We have seen some epic deep traces. Let's say you are in an AspNetCore app. Incoming request creates a root span. Then maybe some span for controller. Then maybe some span for service. Then outgoing Http span. If you log at that 4th level trying to read TraceStateString has to look at all 4 of those spans to see if any have TraceState. Just to drop it or not find it at all. If you are writing a lot of logs, it adds up.

I think of this change as more of us moving into spec compliance with logs. TraceState is not on log data model. Adding it on LogRecord was probably a mistake?

Again I'm not passionate that we need the setting. But I think dropping it by default is good. The setting is to make sure anyone that is actually reliant on the existing behavior can avoid a break.

Alternatively we could obsolete it and tackle this later, but I really don't like the wasted perf 👊

[alanwest]

Appreciate the perf concerns and trying to remedy the fact that we shipped stable logs before the spec was ready, but I vote this moves to a separate PR for discussion. I'd actually prefer we discuss removing tracestate altogether and just deal with any fallout from this breaking change.

[alanwest]

Does it make sense to let feedback drive the need for this option? I like the new behavior or ParseStateValues - it's name is still unfortunate being ILoggery, but I'd prefer to avoid adding another.

[CodeBlanch]

I'm not passionate that we absolutely need this. The idea here is that on this PR I'm redefining (essentially) what ParseStateValues means. If it was false previously we wouldn't look at the state at all and we wouldn't buffer anything for batch cases. With the redefinition, we automatically process state and also automatically buffer things. So I introduced IncludeState to enable what is possible today which is disable the processing & buffering.

[utpilla]

It looks like we would only set the state in the newly added ProcessState method with the requirement that ParseStateValue is also set to false otherwise we could run into situations where state is null even with IncludeState set to true which feels a bit weird.

If we want the new default behavior to always generate attributes, then we could achieve that while continuing to respect the older options. Essentially, we would still only assign one of these: State or StateValues depending on ParseStateValues option but we always generate attributes.

[CodeBlanch]

We could run into situations where state is null even with IncludeState set to true which feels a bit weird.

This is totally by design. State is obsolete. No one should rely on it or use it going forward. It is only set at all to preserve the existing behavior(s) we have today. Maybe it would help to rename IncludeState -> IncludeAttributes? I went ahead and made this change so we could see how it might look. Also updated XML comments to try and document all the behaviors.

Essentially, we would still only assign one of these: State or StateValues depending on ParseStateValues option but we always generate attributes.

I suppose we could do that. But consider an exporter today like GenevaExporter. It checks State and then StateValues. Let's say ParseStateValues = false. So we set State = state, StateValues = null as we do today and then we automatically set Attributes to something useful (new behavior). GenevaExporter now needs an update to take advantage of this. The current behavior on the PR is State = null, StateValues = Attributes = usefulStuff so it will just fall into its existing StateValues branch and doesn't really need to be touched to get the new useful things.

[utpilla]

I think it's better to make the exporters update their implementation to start using new features. I feel by marking State and StateValues oboslete, we essentially want to discourage exporters from using the obsolete properties and use the newer spec complaint properties instead such as Body and Attributes.

Why make it easy for them to continue consuming obsolete properties by providing them newer features through the obsolete properties?

[CodeBlanch]

Interesting perspective. Thinking I would prefer to just drop Attributes and continue along with StateValues. Attributes really isn't a new feature, it is just renaming StateValues to be more compliant with the spec. I like your idea to encourage exporters to update but I don't think this is the best way to go about it. Introducing differences between StateValues and Attributes just seems like unnecessary confusion and documentation burden 😄

Body is a new feature for sure. And it more fits into what you are saying. Exporters have to update if they want to take advantage of it.

[alanwest]

Let's hold off on adding a new configuration option. There's a handful of things going on here.

1. New behavior to StateValues
2. Obsoleting StateValues and introducing Attributes to replace it
3. Introducing IncludeAttributes for configuring old behavior of not processing them by default

I see each of these as a separate PR. I support the first item being in this PR. I also favor doing the second item, but a separate PR would nicely document our conversation and ultimate decision. I'm not in favor of the third item, but happy to continue a focused conversation on a separate PR that introduces it.

[vishweshbankwar]

Should we add any more detail to this obsolete message? Basically, what should one do if they see this obsolete message.

[Yun-Ting]

If I'm the user, I most likely will suppress the warnings in my build until there is a non-backward compatible version got launched and I have to update to that version.

[CodeBlanch]

Should we add any more detail to this obsolete message? Basically, what should one do if they see this obsolete message.

I updated the message so it has more guidance.

If I'm the user, I most likely will suppress the warnings in my build until there is a non-backward compatible version got launched and I have to update to that version.

Fine if that's what people want to do. We may never actually remove the obsolete things 😄 The audience for LogRecord is primarily exporter authors. The number of exporters out there really shouldn't be huge so hopefully we can assist with these updates when they are available.

[Yun-Ting]

Just for my learning, from the description:
"If state is some random unknown object (which should be rare)..."
This would happen under what circumstances?

[CodeBlanch]

@Yun-Ting

Just for my learning, from the description:
"If state is some random unknown object (which should be rare)..."
This would happen under what circumstances?

All logs messages one way or another flow through ILogger.Log. TState doesn't have any contract or constraints.

Probably the most common way to log is via extensions. You do something like logger.LogInformation("Hello {name}", name). There is also a way to pre-generate helpers and there is a source generator. In all of those cases, the .NET code builds a state structure which implements IReadOnlyList<KeyValuePair<string, object?>> for TState when it calls ILogger.Log.

In order to pass a state which does not use IReadOnlyList<KeyValuePair<string, object?>> you have to be going out of your way to call ILogger.Log directly. Like this...

public class MyCustomState
{
  public string Name {get;set;}
}

myLogger.Log(
  LogLevel.Information,
  eventId: default,
  new MyCustomState { Name = "Mike" },
  exception: null,
  formatter: (state, exception) => state.Name);

For that "MyCustomState" log message example prior to this PR users probably wouldn't see any attributes at all. After this PR, we will build attributes as ["Name"] = "Mike" by reflectively looking for top-level public properties (if ParseStateValues == true).

[codecov]

Codecov Report

Merging #4334 (32e48de) into main (bfb3e45) will decrease coverage by 0.09%.
The diff coverage is 74.28%.

Additional details and impacted files

@@            Coverage Diff             @@
##             main    #4334      +/-   ##
==========================================
- Coverage   84.77%   84.69%   -0.09%     
==========================================
  Files         300      300              
  Lines       12010    12064      +54     
==========================================
+ Hits        10182    10218      +36     
- Misses       1828     1846      +18     

Impacted Files	Coverage Δ
...metry.Exporter.Console/ConsoleLogRecordExporter.cs	0.00% <0.00%> (ø)
...ryProtocol.Logs/OtlpLogExporterHelperExtensions.cs	87.50% <ø> (-0.74%)	⬇️
...nTelemetry/Internal/OpenTelemetrySdkEventSource.cs	82.02% <40.00%> (-2.51%)	⬇️
src/OpenTelemetry/Logs/LogRecord.cs	64.88% <67.16%> (-0.81%)	⬇️
src/OpenTelemetry/Logs/OpenTelemetryLogger.cs	88.75% <93.75%> (+1.79%)	⬆️
...etryProtocol/Implementation/LogRecordExtensions.cs	89.15% <100.00%> (ø)
src/OpenTelemetry/Logs/LogRecordData.cs	52.00% <100.00%> (-6.83%)	⬇️
.../OpenTelemetry/Logs/OpenTelemetryLoggerProvider.cs	91.08% <100.00%> (+0.18%)	⬆️
...lemetry/Logs/Options/OpenTelemetryLoggerOptions.cs	100.00% <100.00%> (ø)

... and 6 files with indirect coverage changes

[cijothomas]

Agree to make this public + defaulting to false. (in another PR to reduce scope here)

[utpilla]

@CodeBlanch LGTM to be merged. Left a comment about updating the CHANGELOG. This could be done in a follow-up PR.

[cijothomas]

adding a comment to the PR for anyone wondering: This change is not required really (except to silence warning about using obsolete. The change is backcompatible, so if a Redactor is looking at State or Statealues as before, it'll continue to work, and there is no risk of "Oh damn, I missed to redact secret attributes".

[cijothomas]

Thanks @CodeBlanch for actively driving this forward. Left a nit about changelogs being more clear about what is the impact (or state that there is no impact) for end users.