From 84ea1bbdfbddf9888420e18f34aa613eccf2fd75 Mon Sep 17 00:00:00 2001 From: Mikel Blanchard Date: Wed, 13 Dec 2023 12:48:07 -0800 Subject: [PATCH 1/3] Keep LogRecord.State & LogRecord.Attributes in sync if either is updated by a log processor. --- src/OpenTelemetry/CHANGELOG.md | 4 + .../Logs/ILogger/OpenTelemetryLogger.cs | 4 +- src/OpenTelemetry/Logs/LogRecord.cs | 60 +++- src/OpenTelemetry/Logs/LoggerSdk.cs | 2 +- .../Logs/LogRecordStateProcessorTests.cs | 266 ++++++++++++++++++ 5 files changed, 323 insertions(+), 13 deletions(-) create mode 100644 test/OpenTelemetry.Tests/Logs/LogRecordStateProcessorTests.cs diff --git a/src/OpenTelemetry/CHANGELOG.md b/src/OpenTelemetry/CHANGELOG.md index faa14974dfe..dc7188db5b8 100644 --- a/src/OpenTelemetry/CHANGELOG.md +++ b/src/OpenTelemetry/CHANGELOG.md @@ -2,6 +2,10 @@ ## Unreleased +* `LogRecord.Attributes` and `LogRecord.StateValues` will now automatically + update if `LogRecord.State` is set inside a processor. + ([#XXXX](https://github.com/open-telemetry/opentelemetry-dotnet/pull/XXXX)) + ## 1.7.0 Released 2023-Dec-08 diff --git a/src/OpenTelemetry/Logs/ILogger/OpenTelemetryLogger.cs b/src/OpenTelemetry/Logs/ILogger/OpenTelemetryLogger.cs index 621a66de30c..acdc08f4fdd 100644 --- a/src/OpenTelemetry/Logs/ILogger/OpenTelemetryLogger.cs +++ b/src/OpenTelemetry/Logs/ILogger/OpenTelemetryLogger.cs @@ -79,7 +79,7 @@ public void Log(LogLevel logLevel, EventId eventId, TState state, Except LogRecordData.SetActivityContext(ref data, activity); - var attributes = record.Attributes = + var attributes = record.AttributeData = ProcessState(record, ref iloggerData, in state, this.options.IncludeAttributes, this.options.ParseStateValues); if (!TryGetOriginalFormatFromAttributes(attributes, out var originalFormat)) @@ -133,7 +133,7 @@ internal static void SetLogRecordSeverityFields(ref LogRecordData logRecordData, } } - private static IReadOnlyList>? ProcessState( + internal static IReadOnlyList>? ProcessState( LogRecord logRecord, ref LogRecord.LogRecordILoggerData iLoggerData, in TState state, diff --git a/src/OpenTelemetry/Logs/LogRecord.cs b/src/OpenTelemetry/Logs/LogRecord.cs index a2c06667614..877ab83d1dd 100644 --- a/src/OpenTelemetry/Logs/LogRecord.cs +++ b/src/OpenTelemetry/Logs/LogRecord.cs @@ -18,6 +18,7 @@ public sealed class LogRecord { internal LogRecordData Data; internal LogRecordILoggerData ILoggerData; + internal IReadOnlyList>? AttributeData; internal List>? AttributeStorage; internal List? ScopeStorage; internal int PoolReferenceCount = int.MaxValue; @@ -75,7 +76,7 @@ internal LogRecord( this.Data.Body = template; } - this.Attributes = stateValues; + this.AttributeData = stateValues; } } @@ -228,13 +229,30 @@ public string? Body /// through . /// Set to when is enabled. + /// are automatically updated if is set directly. /// /// [Obsolete("State cannot be accessed safely outside of an ILogger.Log call stack. Use Attributes instead to safely access the data attached to a LogRecord. State will be removed in a future version.")] public object? State { get => this.ILoggerData.State; - set => this.ILoggerData.State = value; + set + { + if (ReferenceEquals(this.ILoggerData.State, value)) + { + return; + } + + if (this.AttributeData is not null) + { + this.AttributeData = OpenTelemetryLogger.ProcessState(this, ref this.ILoggerData, value, includeAttributes: true, parseStateValues: false); + } + else + { + this.ILoggerData.State = value; + } + } } /// @@ -252,15 +270,37 @@ public object? State /// Gets or sets the attributes attached to the log. /// /// - /// Note: Set when is enabled and - /// log record state implements or + /// Set when is enabled and log + /// record state implements or of s /// (where TKey is string and TValue is object) or is enabled - /// otherwise . + /// otherwise . + /// is automatically updated if are set directly. + /// /// - public IReadOnlyList>? Attributes { get; set; } + public IReadOnlyList>? Attributes + { + get => this.AttributeData; + set + { + if (ReferenceEquals(this.AttributeData, value)) + { + return; + } + + if (this.ILoggerData.State is not null) + { + this.ILoggerData.State = value; + } + + this.AttributeData = value; + } + } /// /// Gets or sets the log . @@ -411,7 +451,7 @@ internal LogRecord Copy() { Data = this.Data, ILoggerData = this.ILoggerData.Copy(), - Attributes = this.Attributes == null ? null : new List>(this.Attributes), + AttributeData = this.AttributeData is null ? null : new List>(this.AttributeData), Logger = this.Logger, }; } @@ -422,7 +462,7 @@ internal LogRecord Copy() /// private void BufferLogAttributes() { - var attributes = this.Attributes; + var attributes = this.AttributeData; if (attributes == null || attributes == this.AttributeStorage) { return; @@ -437,7 +477,7 @@ private void BufferLogAttributes() // https://github.com/open-telemetry/opentelemetry-dotnet/issues/2905. attributeStorage.AddRange(attributes); - this.Attributes = attributeStorage; + this.AttributeData = attributeStorage; } /// diff --git a/src/OpenTelemetry/Logs/LoggerSdk.cs b/src/OpenTelemetry/Logs/LoggerSdk.cs index 85f48473690..a0bc47300d0 100644 --- a/src/OpenTelemetry/Logs/LoggerSdk.cs +++ b/src/OpenTelemetry/Logs/LoggerSdk.cs @@ -38,7 +38,7 @@ public override void EmitLog(in LogRecordData data, in LogRecordAttributeList at logRecord.Logger = this; - logRecord.Attributes = attributes.Export(ref logRecord.AttributeStorage); + logRecord.AttributeData = attributes.Export(ref logRecord.AttributeStorage); processor.OnEnd(logRecord); diff --git a/test/OpenTelemetry.Tests/Logs/LogRecordStateProcessorTests.cs b/test/OpenTelemetry.Tests/Logs/LogRecordStateProcessorTests.cs new file mode 100644 index 00000000000..24acd8869a7 --- /dev/null +++ b/test/OpenTelemetry.Tests/Logs/LogRecordStateProcessorTests.cs @@ -0,0 +1,266 @@ +// Copyright The OpenTelemetry Authors +// SPDX-License-Identifier: Apache-2.0 + +#nullable enable + +using System.Diagnostics.CodeAnalysis; +using Microsoft.Extensions.Logging; +using Xunit; + +namespace OpenTelemetry.Logs.Tests; + +public class LogRecordStateProcessorTests +{ + [Theory] + [InlineData(true, false)] + [InlineData(false, true)] + [InlineData(true, true)] + [InlineData(false, false)] + public void LogProcessorSetStateTest(bool includeAttributes, bool parseStateValues) + { + List exportedItems = new(); + + using (var loggerFactory = CreateLoggerFactory(includeAttributes, parseStateValues, exportedItems, OnEnd)) + { + var logger = loggerFactory.CreateLogger("TestLogger"); + + logger.LogInformation("Hello world {data}", 1234); + } + + Assert.Single(exportedItems); + + AssertStateAndAttributes( + exportedItems[0], + attributesExpectedCount: !includeAttributes ? 0 : parseStateValues ? 1 : 3, + stateExpectedCount: !includeAttributes || parseStateValues ? 1 : 3, + out var state, + out var attributes); + + void OnEnd(LogRecord logRecord) + { + AssertStateAndAttributes( + logRecord, + attributesExpectedCount: includeAttributes ? 2 : 0, + stateExpectedCount: !includeAttributes || parseStateValues ? 0 : 2, + out var state, + out var attributes); + + logRecord.State = new List>(state) + { + new("enrichedData", "OTel"), + }; + } + } + + [Theory] + [InlineData(true, false)] + [InlineData(false, true)] + [InlineData(true, true)] + [InlineData(false, false)] + public void LogProcessorSetStateToUnsupportedTypeTest(bool includeAttributes, bool parseStateValues) + { + List exportedItems = new(); + + using (var loggerFactory = CreateLoggerFactory(includeAttributes, parseStateValues, exportedItems, OnEnd)) + { + var logger = loggerFactory.CreateLogger("TestLogger"); + + logger.LogInformation("Hello world {data}", 1234); + } + + Assert.Single(exportedItems); + + AssertStateAndAttributes( + exportedItems[0], + attributesExpectedCount: 0, + stateExpectedCount: 0, + out var state, + out var attributes); + + Assert.True(exportedItems[0].State is CustomState); + + void OnEnd(LogRecord logRecord) + { + AssertStateAndAttributes( + logRecord, + attributesExpectedCount: includeAttributes ? 2 : 0, + stateExpectedCount: !includeAttributes || parseStateValues ? 0 : 2, + out var state, + out var attributes); + + logRecord.State = new CustomState("OTel"); + } + } + + [Theory] + [InlineData(true, false)] + [InlineData(false, true)] + [InlineData(true, true)] + [InlineData(false, false)] + public void LogProcessorSetAttributesTest(bool includeAttributes, bool parseStateValues) + { + List exportedItems = new(); + + using (var loggerFactory = CreateLoggerFactory(includeAttributes, parseStateValues, exportedItems, OnEnd)) + { + var logger = loggerFactory.CreateLogger("TestLogger"); + + logger.LogInformation("Hello world {data}", 1234); + } + + Assert.Single(exportedItems); + + AssertStateAndAttributes( + exportedItems[0], + attributesExpectedCount: !includeAttributes ? 1 : 3, + stateExpectedCount: !includeAttributes || parseStateValues ? 0 : 3, + out var state, + out var attributes); + + void OnEnd(LogRecord logRecord) + { + AssertStateAndAttributes( + logRecord, + attributesExpectedCount: includeAttributes ? 2 : 0, + stateExpectedCount: !includeAttributes || parseStateValues ? 0 : 2, + out var state, + out var attributes); + + logRecord.Attributes = new List>(attributes) + { + new("enrichedData", "OTel"), + }; + } + } + + [Theory] + [InlineData(true, false, 0)] + [InlineData(false, true, 0)] + [InlineData(true, true, 0)] + [InlineData(false, false, 0)] + [InlineData(true, false, 1)] + [InlineData(false, true, 1)] + [InlineData(true, true, 1)] + [InlineData(false, false, 1)] + public void LogProcessorSetAttributesAndStateMixedTest(bool includeAttributes, bool parseStateValues, int order) + { + List exportedItems = new(); + + using (var loggerFactory = CreateLoggerFactory(includeAttributes, parseStateValues, exportedItems, OnEnd)) + { + var logger = loggerFactory.CreateLogger("TestLogger"); + + logger.LogInformation("Hello world {data}", 1234); + } + + Assert.Single(exportedItems); + + AssertStateAndAttributes( + exportedItems[0], + attributesExpectedCount: !includeAttributes ? 1 : 3, + stateExpectedCount: !includeAttributes ? 1 : 3, + out var state, + out var attributes); + + void OnEnd(LogRecord logRecord) + { + AssertStateAndAttributes( + logRecord, + attributesExpectedCount: includeAttributes ? 2 : 0, + stateExpectedCount: !includeAttributes || parseStateValues ? 0 : 2, + out var state, + out var attributes); + + if (order == 0) + { + logRecord.State = logRecord.Attributes = new List>(attributes) + { + new("enrichedData", "OTel"), + }; + } + else + { + var newState = new List>(attributes) + { + new("enrichedData", "OTel"), + }; + + logRecord.State = newState; + logRecord.Attributes = newState; + } + } + } + + private static ILoggerFactory CreateLoggerFactory( + bool includeAttributes, + bool parseStateValues, + List exportedItems, + Action onEndAction) + { + return LoggerFactory.Create(logging => logging + .AddOpenTelemetry(options => + { + options.IncludeAttributes = includeAttributes; + options.ParseStateValues = parseStateValues; + + options + .AddProcessor(new LogRecordStateProcessor(onEndAction)) + .AddInMemoryExporter(exportedItems); + })); + } + + private static void AssertStateAndAttributes( + LogRecord logRecord, + int attributesExpectedCount, + int stateExpectedCount, + [NotNull] out IReadOnlyList>? state, + [NotNull] out IReadOnlyList>? attributes) + { + state = logRecord.State as IReadOnlyList>; + attributes = logRecord.Attributes; + + if (stateExpectedCount > 0) + { + Assert.NotNull(state); + Assert.Equal(stateExpectedCount, state.Count); + } + else + { + Assert.Null(state); + state = Array.Empty>(); + } + + if (attributesExpectedCount > 0) + { + Assert.NotNull(attributes); + Assert.Equal(attributesExpectedCount, attributes.Count); + } + else + { + Assert.Null(attributes); + attributes = Array.Empty>(); + } + } + + private sealed class LogRecordStateProcessor : BaseProcessor + { + private readonly Action onEndAction; + + public LogRecordStateProcessor(Action onEndAction) + { + this.onEndAction = onEndAction; + } + + public override void OnEnd(LogRecord data) + { + this.onEndAction(data); + + base.OnEnd(data); + } + } + + private sealed class CustomState(string enrichedData) + { + public string EnrichedData { get; } = enrichedData; + } +} From b755226f8368052a9fc086be71824326a470025d Mon Sep 17 00:00:00 2001 From: Mikel Blanchard Date: Wed, 13 Dec 2023 13:03:48 -0800 Subject: [PATCH 2/3] CHANGELOG patch. --- src/OpenTelemetry/CHANGELOG.md | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/OpenTelemetry/CHANGELOG.md b/src/OpenTelemetry/CHANGELOG.md index dc7188db5b8..8fd9e23d498 100644 --- a/src/OpenTelemetry/CHANGELOG.md +++ b/src/OpenTelemetry/CHANGELOG.md @@ -4,7 +4,7 @@ * `LogRecord.Attributes` and `LogRecord.StateValues` will now automatically update if `LogRecord.State` is set inside a processor. - ([#XXXX](https://github.com/open-telemetry/opentelemetry-dotnet/pull/XXXX)) + ([#5169](https://github.com/open-telemetry/opentelemetry-dotnet/pull/5169)) ## 1.7.0 From 585860dccd5d7607411ee064157be5ba7568c651 Mon Sep 17 00:00:00 2001 From: Mikel Blanchard Date: Thu, 14 Dec 2023 16:15:24 -0800 Subject: [PATCH 3/3] CHANGELOG tweak. --- src/OpenTelemetry/CHANGELOG.md | 9 ++++++--- 1 file changed, 6 insertions(+), 3 deletions(-) diff --git a/src/OpenTelemetry/CHANGELOG.md b/src/OpenTelemetry/CHANGELOG.md index 8fd9e23d498..f760d475655 100644 --- a/src/OpenTelemetry/CHANGELOG.md +++ b/src/OpenTelemetry/CHANGELOG.md @@ -2,9 +2,12 @@ ## Unreleased -* `LogRecord.Attributes` and `LogRecord.StateValues` will now automatically - update if `LogRecord.State` is set inside a processor. - ([#5169](https://github.com/open-telemetry/opentelemetry-dotnet/pull/5169)) +* Fixed an issue where `LogRecord.Attributes` (or `LogRecord.StateValues` alias) + could become out of sync with `LogRecord.State` if either is set directly via + the public setters. This was done to further mitigate issues introduced in + 1.5.0 causing attributes added using custom processor(s) to be missing after + upgrading. For details see: + [#5169](https://github.com/open-telemetry/opentelemetry-dotnet/pull/5169) ## 1.7.0