[Logs] Fix buffered log scopes being reused (#3731)

* Fix buffered log scopes being reused. * CHANGELOG update. * Test fixes. Co-authored-by: Cijo Thomas <cithomas@microsoft.com>
open-telemetry · Oct 5, 2022 · 7f71283 · 7f71283
1 parent d42f171
commit 7f71283
Show file tree

Hide file tree

Showing 7 changed files with 88 additions and 19 deletions.
diff --git 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
@@ -33,6 +33,7 @@ public sealed class LogRecord
     {
         internal LogRecordData Data;
         internal List<KeyValuePair<string, object?>>? AttributeStorage;
+        internal List<object?>? ScopeStorage;
         internal List<object?>? BufferedScopes;
         internal int PoolReferenceCount = int.MaxValue;
 
@@ -309,11 +310,13 @@ private void BufferLogScopes()
                 return;
             }
 
-            List<object?> scopes = this.BufferedScopes ??= new List<object?>(LogRecordPoolHelper.DefaultMaxNumberOfScopes);
+            var scopeStorage = this.ScopeStorage ??= new List<object?>(LogRecordPoolHelper.DefaultMaxNumberOfScopes);
 
-            this.ScopeProvider.ForEachScope(AddScopeToBufferedList, scopes);
+            this.ScopeProvider.ForEachScope(AddScopeToBufferedList, scopeStorage);
 
             this.ScopeProvider = null;
+
+            this.BufferedScopes = scopeStorage;
         }
 
         private readonly struct ScopeForEachState<TState>

diff --git a/src/OpenTelemetry/Logs/OpenTelemetryLogger.cs b/src/OpenTelemetry/Logs/OpenTelemetryLogger.cs
@@ -60,6 +60,7 @@ public void Log<TState>(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
@@ -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<T>.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
@@ -136,19 +136,19 @@ public void ClearTests()
                 new KeyValuePair<string, object?>("key1", "value1"),
                 new KeyValuePair<string, object?>("key2", "value2"),
             };
-            logRecord1.BufferedScopes = new List<object?>(8) { null, null };
+            logRecord1.ScopeStorage = new List<object?>(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
@@ -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<LogRecord> exportedItems, Action<OpenTelemetryLoggerOptions> configure = null)
         {
             var items = exportedItems = new List<LogRecord>();
@@ -915,6 +948,33 @@ private class CustomState
         {
             public string Property { get; set; }
         }
+
+        private class ScopeProcessor : BaseProcessor<LogRecord>
+        {
+            private readonly bool buffer;
+
+            public ScopeProcessor(bool buffer)
+            {
+                this.buffer = buffer;
+            }
+
+            public List<object> Scopes { get; } = new();
+
+            public override void OnEnd(LogRecord data)
+            {
+                data.ForEachScope<object>(
+                    (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
@@ -57,19 +57,19 @@ public void ClearTests()
                 new KeyValuePair<string, object?>("key1", "value1"),
                 new KeyValuePair<string, object?>("key2", "value2"),
             };
-            logRecord1.BufferedScopes = new List<object?>(8) { null, null };
+            logRecord1.ScopeStorage = new List<object?>(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);
         }
     }
 }