[sdk-1.5.0-hotfix] Fix LogRecord.State being null when TState matches known interfaces #4609

CodeBlanch · 2023-06-23T19:06:36Z

Note: This PR is targeting main-1.5.0 branch.

Changes

Restores 1.4.0 logic for LogRecord.State handling.

Details

1.5.0 tweaked OpenTelemetryLoggerOptions.ParseStateValues so that if logged TState is IReadOnlyList or IEnumerable of KeyValuePair<string, object> we automatically set LogRecord.Attributes \ LogRecord.StateValues and leave LogRecord.State = null. The idea with that is exporters were coded like this...

if (logRecord.StateValues != null)
{
    attributes = logRecord.StateValues;
}
else
{
    attributes = logRecord.State as IReadOnlyList<KeyValuePair<string, object>>;
}

What was reported is an exporter doing this...

var attributes = (IReadOnlyCollection<KeyValuePair<string, object>>)logRecord.State;

Which throws a NRE with the new logic.

In order to preserve the above logic this PR puts back handling of LogRecord.State so that it is always set so long as OpenTelemetryLoggerOptions.ParseStateValues == false (the previous behavior).

Merge requirement checklist

CONTRIBUTING guidelines followed (nullable enabled, static analysis, etc.)
Unit tests added/updated
Appropriate CHANGELOG.md files updated for non-trivial changes

codecov · 2023-06-23T19:23:58Z

Codecov Report

Merging #4609 (3a46aeb) into main-1.5.0 (494323b) will increase coverage by 0.00%.
The diff coverage is 100.00%.

Additional details and impacted files

@@             Coverage Diff             @@
##           main-1.5.0    #4609   +/-   ##
===========================================
  Coverage       85.57%   85.57%           
===========================================
  Files             320      320           
  Lines           12615    12620    +5     
===========================================
+ Hits            10795    10800    +5     
  Misses           1820     1820

Impacted Files	Coverage Δ
.../OpenTelemetry/Logs/ILogger/OpenTelemetryLogger.cs	`88.28% <100.00%> (+0.55%)`	⬆️

... and 6 files with indirect coverage changes

utpilla · 2023-06-23T21:13:32Z

src/OpenTelemetry/Logs/ILogger/OpenTelemetryLogger.cs

        bool parseStateValues)
    {
-        iLoggerData.State = null;
+        if (!includeAttributes)


Add check for state == null here and remove the else if condition here?

Suggested change

if (!includeAttributes)

if (!includeAttributes || state is null)

I think the else if could only be removed if we also take your suggestion:

How about we also remove the support for parsing custom typed objects as well in 1.5.1? This PR #4560 is doing that anyway?

Right?

My thinking here was most states will not be null so better to not spend cycles checking for uncommon case until it is needed. But I moved it up and rewrote the check so that the JIT should elide it for structs completely so there shouldn't be any impact.

utpilla · 2023-06-23T21:21:45Z

How about we also remove the support for parsing custom typed objects as well in 1.5.1? This PR #4560 is doing that anyway?

CodeBlanch · 2023-06-23T21:39:05Z

How about we also remove the support for parsing custom typed objects as well in 1.5.1? This PR #4560 is doing that anyway?

I think for a hotfix we should keep it small and focused. But if you want to also do that in there we can do on a follow-up.

alanwest · 2023-06-23T21:41:24Z

How about we also remove the support for parsing custom typed objects as well in 1.5.1? This PR #4560 is doing that anyway?

I think for a hotfix we should keep it small and focused. But if you want to also do that in there we can do on a follow-up.

Also agree should be a separate PR. Though, is there a strong reason #4560 should ship in 1.5.1?

utpilla · 2023-06-23T21:44:51Z

Also agree should be a separate PR.

I agree to that as well.

Though, is there a strong reason #4560 should ship in 1.5.1?

I think it's better to treat that as an unwanted change (bug?) added in 1.5.0 and remove it for 1.5.1 instead of making a breaking change in 1.6.0.

alanwest · 2023-06-23T23:33:09Z

I think it's better to treat that as an unwanted change (bug?)

👍 I support this reasoning.

reyang · 2023-06-23T23:53:02Z

I think it's better to treat that as an unwanted change (bug?) added in 1.5.0 and remove it for 1.5.1 instead of making a breaking change in 1.6.0.

+1 Good judgement!

test/OpenTelemetry.Exporter.OpenTelemetryProtocol.Tests/OtlpLogExporterTests.cs

CodeBlanch · 2023-06-26T17:04:21Z

I just pushed a change...

Removed the date from the CHANGELOG since it seems like we will be doing more for the hotfix.
Updated the logic after doing some perf testing:

It seems the compiler is not smart enough to know when it has boxed some struct. The code was flowing like this:

logRecord.State = state; // boxing 1
if (state is IReadOnlyList<KeyValuePair<string, object?>> stateList)) // boxing 2

This PR makes the memory perf twice as bad and the CPU has to do more work 🤮

I changed it to do this...

if (state is IReadOnlyList<KeyValuePair<string, object?>> stateList))
{
    logRecord.State = stateList; // reuse boxing of state to IReadOnlyList
}
else
{
    logRecord.State = state; // box directly if all else failed
}

It is more code but the perf justifies it IMO.

Benchmarks

[MemoryDiagnoser]
public class BoxingBenchmarks
{
    [Benchmark]
    public (object State, int Count) AssignToObjectFirstAndThenCastAsInterface()
    {
        var data = default(TestStruct);

        var state = (object)data;

        if (data is IReadOnlyList<KeyValuePair<string, object>> list)
        {
            return (state, list.Count);
        }

        return (state, -1);
    }

    [Benchmark]
    public (object State, int Count) CastAsInterfaceAndThenAssignAsState()
    {
        var data = default(TestStruct);

        if (data is IReadOnlyList<KeyValuePair<string, object>> list)
        {
            return (list, list.Count);
        }

        return ((object)data, -1);
    }

    public struct TestStruct : IReadOnlyList<KeyValuePair<string, object>>
    {
        public int IntValue;
        public double DoubleValue;
        public object RefValue;

        public readonly int Count => 0;

        public readonly KeyValuePair<string, object> this[int index] => throw new NotImplementedException();

        public IEnumerator<KeyValuePair<string, object>> GetEnumerator()
        {
            throw new NotImplementedException();
        }

        IEnumerator IEnumerable.GetEnumerator()
        {
            throw new NotImplementedException();
        }
    }
}

Method	Mean	Error	StdDev	Gen0	Gen1	Allocated
AssignToObjectFirstAndThenCastAsInterface	7.717 ns	0.1748 ns	0.1460 ns	0.0064	0.0000	80 B
CastAsInterfaceAndThenAssignAsState	4.945 ns	0.1083 ns	0.1013 ns	0.0032	0.0000	40 B

CodeBlanch added 2 commits June 23, 2023 11:53

Fixed LogRecord.State being null when TState matches known interfaces.

6914beb

Test fix.

a09d575

CodeBlanch requested a review from a team as a code owner June 23, 2023 19:06

CHANGELOG patch.

e0f6532

utpilla reviewed Jun 23, 2023

View reviewed changes

reyang approved these changes Jun 23, 2023

View reviewed changes

Code review.

cdec06f

alanwest approved these changes Jun 23, 2023

View reviewed changes

Warning cleanup.

82b33b4

utpilla approved these changes Jun 23, 2023

View reviewed changes

vishweshbankwar reviewed Jun 26, 2023

View reviewed changes

test/OpenTelemetry.Exporter.OpenTelemetryProtocol.Tests/OtlpLogExporterTests.cs Show resolved Hide resolved

vishweshbankwar approved these changes Jun 26, 2023

View reviewed changes

Perf tweaks.

3a46aeb

CodeBlanch merged commit ae03840 into open-telemetry:main-1.5.0 Jun 26, 2023
29 checks passed

CodeBlanch deleted the main-1.5.0-logginghotfix branch June 26, 2023 17:19

This was referenced Jun 26, 2023

[sdk-1.5.0-hotfix] Removed support for parsing custom log states using reflection #4614

Merged

[sdk] Merge 1.5.1 fixes to main (1.6 dev) #4619

Merged

CodeBlanch mentioned this pull request Dec 13, 2023

[sdk-logs] Keep LogRecord.State & LogRecord.Attributes in sync if either is updated by a log processor #5169

Merged

3 tasks

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

[sdk-1.5.0-hotfix] Fix LogRecord.State being null when TState matches known interfaces #4609

[sdk-1.5.0-hotfix] Fix LogRecord.State being null when TState matches known interfaces #4609

CodeBlanch commented Jun 23, 2023 •

edited

Loading

codecov bot commented Jun 23, 2023 •

edited

Loading

utpilla Jun 23, 2023 •

edited

Loading

alanwest Jun 23, 2023

CodeBlanch Jun 23, 2023

utpilla commented Jun 23, 2023 •

edited

Loading

CodeBlanch commented Jun 23, 2023

alanwest commented Jun 23, 2023

utpilla commented Jun 23, 2023

alanwest commented Jun 23, 2023

reyang commented Jun 23, 2023

CodeBlanch commented Jun 26, 2023

	if (!includeAttributes)
	if (!includeAttributes \|\| state is null)

[sdk-1.5.0-hotfix] Fix LogRecord.State being null when TState matches known interfaces #4609

[sdk-1.5.0-hotfix] Fix LogRecord.State being null when TState matches known interfaces #4609

Conversation

CodeBlanch commented Jun 23, 2023 • edited Loading

Changes

Details

Merge requirement checklist

codecov bot commented Jun 23, 2023 • edited Loading

Codecov Report

utpilla Jun 23, 2023 • edited Loading

Choose a reason for hiding this comment

alanwest Jun 23, 2023

Choose a reason for hiding this comment

CodeBlanch Jun 23, 2023

Choose a reason for hiding this comment

utpilla commented Jun 23, 2023 • edited Loading

CodeBlanch commented Jun 23, 2023

alanwest commented Jun 23, 2023

utpilla commented Jun 23, 2023

alanwest commented Jun 23, 2023

reyang commented Jun 23, 2023

CodeBlanch commented Jun 26, 2023

CodeBlanch commented Jun 23, 2023 •

edited

Loading

codecov bot commented Jun 23, 2023 •

edited

Loading

utpilla Jun 23, 2023 •

edited

Loading

utpilla commented Jun 23, 2023 •

edited

Loading