diff --git a/src/OpenTelemetry/CHANGELOG.md b/src/OpenTelemetry/CHANGELOG.md index bcd7388b28b..1b7d64f1804 100644 --- a/src/OpenTelemetry/CHANGELOG.md +++ b/src/OpenTelemetry/CHANGELOG.md @@ -7,6 +7,11 @@ ## Unreleased +* Fixed an issue where `LogRecord.ForEachScope` may return scopes from a + previous log if accessed in a custom processor before + `BatchLogRecordExportProcessor.OnEnd` is fired. + ([#3731](https://github.com/open-telemetry/opentelemetry-dotnet/pull/3731)) + ## 1.4.0-beta.1 Released 2022-Sep-29 diff --git a/src/OpenTelemetry/Logs/ILogger/OpenTelemetryLogger.cs b/src/OpenTelemetry/Logs/ILogger/OpenTelemetryLogger.cs index c5107dec35e..d8c8bdad9c7 100644 --- a/src/OpenTelemetry/Logs/ILogger/OpenTelemetryLogger.cs +++ b/src/OpenTelemetry/Logs/ILogger/OpenTelemetryLogger.cs @@ -75,6 +75,8 @@ public void Log(LogLevel logLevel, EventId eventId, TState state, Except iloggerData.CategoryName = this.categoryName; iloggerData.EventId = eventId; iloggerData.Exception = exception; + iloggerData.ScopeProvider = iloggerProvider.IncludeScopes ? this.ScopeProvider : null; + iloggerData.BufferedScopes = null; ref LogRecordData data = ref record.Data; @@ -114,9 +116,8 @@ public void Log(LogLevel logLevel, EventId eventId, TState state, Except iloggerData.FormattedMessage = iloggerProvider.IncludeFormattedMessage ? formatter?.Invoke(state, exception) : null; } - record.ScopeProvider = iloggerProvider.IncludeScopes ? this.ScopeProvider : null; processor.OnEnd(record); - record.ScopeProvider = null; + iloggerData.ScopeProvider = null; // Attempt to return the LogRecord to the pool. This will no-op // if a batch exporter has added a reference. diff --git a/src/OpenTelemetry/Logs/LogRecord.cs b/src/OpenTelemetry/Logs/LogRecord.cs index f417ee86693..3e8836d8df5 100644 --- a/src/OpenTelemetry/Logs/LogRecord.cs +++ b/src/OpenTelemetry/Logs/LogRecord.cs @@ -34,7 +34,7 @@ public sealed class LogRecord internal LogRecordData Data; internal LogRecordILoggerData ILoggerData; internal List>? AttributeStorage; - internal List? BufferedScopes; + internal List? ScopeStorage; internal int PoolReferenceCount = int.MaxValue; private static readonly Action> AddScopeToBufferedList = (object? scope, List state) => @@ -75,6 +75,7 @@ internal LogRecord( EventId = eventId, Exception = exception, State = state, + ScopeProvider = scopeProvider, }; if (stateValues != null && stateValues.Count > 0) @@ -90,8 +91,6 @@ internal LogRecord( this.InstrumentationScope = null; this.Attributes = stateValues; - - this.ScopeProvider = scopeProvider; } /// @@ -262,8 +261,6 @@ public LogRecordSeverity? Severity /// public InstrumentationScope? InstrumentationScope { get; internal set; } - internal IExternalScopeProvider? ScopeProvider { get; set; } - /// /// Executes callback for each currently active scope objects in order /// of creation. All callbacks are guaranteed to be called inline from @@ -281,16 +278,16 @@ public void ForEachScope(Action callback, TState var forEachScopeState = new ScopeForEachState(callback, state); - if (this.BufferedScopes != null) + if (this.ILoggerData.BufferedScopes != null) { - foreach (object? scope in this.BufferedScopes) + foreach (object? scope in this.ILoggerData.BufferedScopes) { ScopeForEachState.ForEachScope(scope, forEachScopeState); } } else { - this.ScopeProvider?.ForEachScope(ScopeForEachState.ForEachScope, forEachScopeState); + this.ILoggerData.ScopeProvider?.ForEachScope(ScopeForEachState.ForEachScope, forEachScopeState); } } @@ -330,13 +327,14 @@ internal LogRecord Copy() // directly below. this.BufferLogScopes(); - return new() + var copy = new LogRecord() { Data = this.Data, - ILoggerData = this.ILoggerData, + ILoggerData = this.ILoggerData.Copy(), Attributes = this.Attributes == null ? null : new List>(this.Attributes), - BufferedScopes = this.BufferedScopes == null ? null : new List(this.BufferedScopes), }; + + return copy; } /// @@ -370,16 +368,19 @@ private void BufferLogAttributes() /// private void BufferLogScopes() { - if (this.ScopeProvider == null) + var scopeProvider = this.ILoggerData.ScopeProvider; + if (scopeProvider == null) { return; } - List scopes = this.BufferedScopes ??= new List(LogRecordPoolHelper.DefaultMaxNumberOfScopes); + var scopeStorage = this.ScopeStorage ??= new List(LogRecordPoolHelper.DefaultMaxNumberOfScopes); - this.ScopeProvider.ForEachScope(AddScopeToBufferedList, scopes); + scopeProvider.ForEachScope(AddScopeToBufferedList, scopeStorage); - this.ScopeProvider = null; + this.ILoggerData.ScopeProvider = null; + + this.ILoggerData.BufferedScopes = scopeStorage; } internal struct LogRecordILoggerData @@ -390,6 +391,29 @@ internal struct LogRecordILoggerData public string? FormattedMessage; public Exception? Exception; public object? State; + public IExternalScopeProvider? ScopeProvider; + public List? BufferedScopes; + + public LogRecordILoggerData Copy() + { + var copy = new LogRecordILoggerData + { + TraceState = this.TraceState, + CategoryName = this.CategoryName, + EventId = this.EventId, + FormattedMessage = this.FormattedMessage, + Exception = this.Exception, + State = this.State, + }; + + var bufferedScopes = this.BufferedScopes; + if (bufferedScopes != null) + { + copy.BufferedScopes = new List(bufferedScopes); + } + + return copy; + } } private readonly struct ScopeForEachState diff --git a/src/OpenTelemetry/Logs/Pool/LogRecordPoolHelper.cs b/src/OpenTelemetry/Logs/Pool/LogRecordPoolHelper.cs index b63028b920b..e024e72063e 100644 --- a/src/OpenTelemetry/Logs/Pool/LogRecordPoolHelper.cs +++ b/src/OpenTelemetry/Logs/Pool/LogRecordPoolHelper.cs @@ -41,19 +41,19 @@ underlying array (capacity). */ } } - var bufferedScopes = logRecord.BufferedScopes; - if (bufferedScopes != null) + var scopeStorage = logRecord.ScopeStorage; + if (scopeStorage != null) { - if (bufferedScopes.Count > DefaultMaxNumberOfScopes) + if (scopeStorage.Count > DefaultMaxNumberOfScopes) { // Don't allow the pool to grow unconstained. - logRecord.BufferedScopes = null; + logRecord.ScopeStorage = null; } else { /* List.Clear sets the count/size to 0 but it maintains the underlying array (capacity). */ - bufferedScopes.Clear(); + scopeStorage.Clear(); } } } diff --git a/test/OpenTelemetry.Tests/Logs/BatchLogRecordExportProcessorTests.cs b/test/OpenTelemetry.Tests/Logs/BatchLogRecordExportProcessorTests.cs index 95295f1b482..105f848a796 100644 --- a/test/OpenTelemetry.Tests/Logs/BatchLogRecordExportProcessorTests.cs +++ b/test/OpenTelemetry.Tests/Logs/BatchLogRecordExportProcessorTests.cs @@ -41,7 +41,7 @@ public void StateValuesAndScopeBufferingTest() var state = new LogRecordTest.DisposingState("Hello world"); - logRecord.ScopeProvider = scopeProvider; + logRecord.ILoggerData.ScopeProvider = scopeProvider; logRecord.StateValues = state; processor.OnEnd(logRecord); @@ -50,10 +50,10 @@ public void StateValuesAndScopeBufferingTest() Assert.Empty(exportedItems); - Assert.Null(logRecord.ScopeProvider); + Assert.Null(logRecord.ILoggerData.ScopeProvider); Assert.False(ReferenceEquals(state, logRecord.StateValues)); Assert.NotNull(logRecord.AttributeStorage); - Assert.NotNull(logRecord.BufferedScopes); + Assert.NotNull(logRecord.ILoggerData.BufferedScopes); KeyValuePair actualState = logRecord.StateValues[0]; diff --git a/test/OpenTelemetry.Tests/Logs/LogRecordSharedPoolTests.cs b/test/OpenTelemetry.Tests/Logs/LogRecordSharedPoolTests.cs index 0a6d7d37baf..2541c5cc5db 100644 --- a/test/OpenTelemetry.Tests/Logs/LogRecordSharedPoolTests.cs +++ b/test/OpenTelemetry.Tests/Logs/LogRecordSharedPoolTests.cs @@ -136,19 +136,19 @@ public void ClearTests() new KeyValuePair("key1", "value1"), new KeyValuePair("key2", "value2"), }; - logRecord1.BufferedScopes = new List(8) { null, null }; + logRecord1.ScopeStorage = new List(8) { null, null }; pool.Return(logRecord1); Assert.Empty(logRecord1.AttributeStorage); Assert.Equal(16, logRecord1.AttributeStorage.Capacity); - Assert.Empty(logRecord1.BufferedScopes); - Assert.Equal(8, logRecord1.BufferedScopes.Capacity); + Assert.Empty(logRecord1.ScopeStorage); + Assert.Equal(8, logRecord1.ScopeStorage.Capacity); logRecord1 = pool.Rent(); Assert.NotNull(logRecord1.AttributeStorage); - Assert.NotNull(logRecord1.BufferedScopes); + Assert.NotNull(logRecord1.ScopeStorage); for (int i = 0; i <= LogRecordPoolHelper.DefaultMaxNumberOfAttributes; i++) { @@ -157,13 +157,13 @@ public void ClearTests() for (int i = 0; i <= LogRecordPoolHelper.DefaultMaxNumberOfScopes; i++) { - logRecord1.BufferedScopes!.Add(null); + logRecord1.ScopeStorage!.Add(null); } pool.Return(logRecord1); Assert.Null(logRecord1.AttributeStorage); - Assert.Null(logRecord1.BufferedScopes); + Assert.Null(logRecord1.ScopeStorage); } [Theory] diff --git a/test/OpenTelemetry.Tests/Logs/LogRecordTest.cs b/test/OpenTelemetry.Tests/Logs/LogRecordTest.cs index 65a65745099..8f521c649bb 100644 --- a/test/OpenTelemetry.Tests/Logs/LogRecordTest.cs +++ b/test/OpenTelemetry.Tests/Logs/LogRecordTest.cs @@ -934,6 +934,39 @@ public void DisposingStateTest() Assert.Same("Hello world", actualState.Value); } + [Theory] + [InlineData(true)] + [InlineData(false)] + public void ReusedLogRecordScopeTest(bool buffer) + { + var processor = new ScopeProcessor(buffer); + + using var loggerFactory = LoggerFactory.Create(builder => + { + builder.AddOpenTelemetry(options => + { + options.IncludeScopes = true; + options.AddProcessor(processor); + }); + }); + + var logger = loggerFactory.CreateLogger("TestLogger"); + + using (var scope1 = logger.BeginScope("scope1")) + { + logger.LogInformation("message1"); + } + + using (var scope2 = logger.BeginScope("scope2")) + { + logger.LogInformation("message2"); + } + + Assert.Equal(2, processor.Scopes.Count); + Assert.Equal("scope1", processor.Scopes[0]); + Assert.Equal("scope2", processor.Scopes[1]); + } + private static ILoggerFactory InitializeLoggerFactory(out List exportedItems, Action configure = null) { var items = exportedItems = new List(); @@ -1084,5 +1117,32 @@ private class CustomState public string Property3 { get; set; } } + + private class ScopeProcessor : BaseProcessor + { + private readonly bool buffer; + + public ScopeProcessor(bool buffer) + { + this.buffer = buffer; + } + + public List Scopes { get; } = new(); + + public override void OnEnd(LogRecord data) + { + data.ForEachScope( + (scope, state) => + { + this.Scopes.Add(scope.Scope); + }, + null); + + if (this.buffer) + { + data.Buffer(); + } + } + } } } diff --git a/test/OpenTelemetry.Tests/Logs/LogRecordThreadStaticPoolTests.cs b/test/OpenTelemetry.Tests/Logs/LogRecordThreadStaticPoolTests.cs index 93a334cc567..f683609c013 100644 --- a/test/OpenTelemetry.Tests/Logs/LogRecordThreadStaticPoolTests.cs +++ b/test/OpenTelemetry.Tests/Logs/LogRecordThreadStaticPoolTests.cs @@ -57,19 +57,19 @@ public void ClearTests() new KeyValuePair("key1", "value1"), new KeyValuePair("key2", "value2"), }; - logRecord1.BufferedScopes = new List(8) { null, null }; + logRecord1.ScopeStorage = new List(8) { null, null }; LogRecordThreadStaticPool.Instance.Return(logRecord1); Assert.Empty(logRecord1.AttributeStorage); Assert.Equal(16, logRecord1.AttributeStorage.Capacity); - Assert.Empty(logRecord1.BufferedScopes); - Assert.Equal(8, logRecord1.BufferedScopes.Capacity); + Assert.Empty(logRecord1.ScopeStorage); + Assert.Equal(8, logRecord1.ScopeStorage.Capacity); logRecord1 = LogRecordThreadStaticPool.Instance.Rent(); Assert.NotNull(logRecord1.AttributeStorage); - Assert.NotNull(logRecord1.BufferedScopes); + Assert.NotNull(logRecord1.ScopeStorage); for (int i = 0; i <= LogRecordPoolHelper.DefaultMaxNumberOfAttributes; i++) { @@ -78,13 +78,13 @@ public void ClearTests() for (int i = 0; i <= LogRecordPoolHelper.DefaultMaxNumberOfScopes; i++) { - logRecord1.BufferedScopes!.Add(null); + logRecord1.ScopeStorage!.Add(null); } LogRecordThreadStaticPool.Instance.Return(logRecord1); Assert.Null(logRecord1.AttributeStorage); - Assert.Null(logRecord1.BufferedScopes); + Assert.Null(logRecord1.ScopeStorage); } } }