[Logs-branch] Port scope buffering fix to logs branch (#3736)

* [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>

* Update log scope buffering fix for new api.

Co-authored-by: Cijo Thomas <cithomas@microsoft.com>

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

src/OpenTelemetry/Logs/ILogger/OpenTelemetryLogger.cs

@@ -75,6 +75,8 @@ public void Log<TState>(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<TState>(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.

src/OpenTelemetry/Logs/LogRecord.cs

@@ -34,7 +34,7 @@ public sealed class LogRecord
         internal LogRecordData Data;
         internal LogRecordILoggerData ILoggerData;
         internal List<KeyValuePair<string, object?>>? AttributeStorage;
-        internal List<object?>? BufferedScopes;
+        internal List<object?>? ScopeStorage;
         internal int PoolReferenceCount = int.MaxValue;
 
         private static readonly Action<object?, List<object?>> AddScopeToBufferedList = (object? scope, List<object?> 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;
         }
 
         /// <summary>
@@ -262,8 +261,6 @@ public LogRecordSeverity? Severity
         /// </summary>
         public InstrumentationScope? InstrumentationScope { get; internal set; }
 
-        internal IExternalScopeProvider? ScopeProvider { get; set; }
-
         /// <summary>
         /// 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<TState>(Action<LogRecordScope, TState> callback, TState
 
             var forEachScopeState = new ScopeForEachState<TState>(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<TState>.ForEachScope(scope, forEachScopeState);
                 }
             }
             else
             {
-                this.ScopeProvider?.ForEachScope(ScopeForEachState<TState>.ForEachScope, forEachScopeState);
+                this.ILoggerData.ScopeProvider?.ForEachScope(ScopeForEachState<TState>.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<KeyValuePair<string, object?>>(this.Attributes),
-                BufferedScopes = this.BufferedScopes == null ? null : new List<object?>(this.BufferedScopes),
             };
+
+            return copy;
         }
 
         /// <summary>
@@ -370,16 +368,19 @@ private void BufferLogAttributes()
         /// </summary>
         private void BufferLogScopes()
         {
-            if (this.ScopeProvider == null)
+            var scopeProvider = this.ILoggerData.ScopeProvider;
+            if (scopeProvider == null)
             {
                 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);
+            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<object?>? 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<object?>(bufferedScopes);
+                }
+
+                return copy;
+            }
         }
 
         private readonly struct ScopeForEachState<TState>

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();
                 }
             }
         }

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<string, object> actualState = logRecord.StateValues[0];
 

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]

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<LogRecord> exportedItems, Action<OpenTelemetryLoggerOptions> configure = null)
         {
             var items = exportedItems = new List<LogRecord>();
@@ -1084,5 +1117,32 @@ private class CustomState
 
             public string Property3 { 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();
+                }
+            }
+        }
     }
 }

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);
         }
     }
 }