From 7f71283c0bf2ee0e2c5e3c9617295ddaf20c7a0c Mon Sep 17 00:00:00 2001 From: Mikel Blanchard Date: Wed, 5 Oct 2022 13:42:33 -0700 Subject: [PATCH] [Logs] Fix buffered log scopes being reused (#3731) * Fix buffered log scopes being reused. * CHANGELOG update. * Test fixes. Co-authored-by: Cijo Thomas --- src/OpenTelemetry/CHANGELOG.md | 5 ++ src/OpenTelemetry/Logs/LogRecord.cs | 7 ++- src/OpenTelemetry/Logs/OpenTelemetryLogger.cs | 1 + .../Logs/Pool/LogRecordPoolHelper.cs | 10 ++-- .../Logs/LogRecordSharedPoolTests.cs | 12 ++-- .../OpenTelemetry.Tests/Logs/LogRecordTest.cs | 60 +++++++++++++++++++ .../Logs/LogRecordThreadStaticPoolTests.cs | 12 ++-- 7 files changed, 88 insertions(+), 19 deletions(-) diff --git a/src/OpenTelemetry/CHANGELOG.md b/src/OpenTelemetry/CHANGELOG.md index 58afdc44a34..417e252b800 100644 --- a/src/OpenTelemetry/CHANGELOG.md +++ b/src/OpenTelemetry/CHANGELOG.md @@ -2,6 +2,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/LogRecord.cs b/src/OpenTelemetry/Logs/LogRecord.cs index 61c8199391c..1991b94fe0f 100644 --- a/src/OpenTelemetry/Logs/LogRecord.cs +++ b/src/OpenTelemetry/Logs/LogRecord.cs @@ -33,6 +33,7 @@ public sealed class LogRecord { internal LogRecordData Data; internal List>? AttributeStorage; + internal List? ScopeStorage; internal List? BufferedScopes; internal int PoolReferenceCount = int.MaxValue; @@ -309,11 +310,13 @@ private void BufferLogScopes() return; } - List scopes = this.BufferedScopes ??= new List(LogRecordPoolHelper.DefaultMaxNumberOfScopes); + var scopeStorage = this.ScopeStorage ??= new List(LogRecordPoolHelper.DefaultMaxNumberOfScopes); - this.ScopeProvider.ForEachScope(AddScopeToBufferedList, scopes); + this.ScopeProvider.ForEachScope(AddScopeToBufferedList, scopeStorage); this.ScopeProvider = null; + + this.BufferedScopes = scopeStorage; } private readonly struct ScopeForEachState diff --git a/src/OpenTelemetry/Logs/OpenTelemetryLogger.cs b/src/OpenTelemetry/Logs/OpenTelemetryLogger.cs index 91698d1123a..4c5cfc6bcf5 100644 --- a/src/OpenTelemetry/Logs/OpenTelemetryLogger.cs +++ b/src/OpenTelemetry/Logs/OpenTelemetryLogger.cs @@ -60,6 +60,7 @@ public void Log(LogLevel logLevel, EventId eventId, TState state, Except record.ScopeProvider = provider.IncludeScopes ? this.ScopeProvider : null; record.State = provider.ParseStateValues ? null : state; record.StateValues = provider.ParseStateValues ? ParseState(record, state) : null; + record.BufferedScopes = null; ref LogRecordData data = ref record.Data; 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/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 79fb0d2fa19..02b39395a72 100644 --- a/test/OpenTelemetry.Tests/Logs/LogRecordTest.cs +++ b/test/OpenTelemetry.Tests/Logs/LogRecordTest.cs @@ -771,6 +771,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(); @@ -915,6 +948,33 @@ private class CustomState { public string Property { 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(); + } + } + } } } #endif 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); } } }