Logs: Scope improvements (#2026)

docs/logs/extending-the-sdk/MyExporter.cs

@@ -44,12 +44,21 @@ public override ExportResult Export(in Batch<LogRecord> batch)
 
             sb.Append($"{record}(");
 
+            int scopeDepth = -1;
+
             record.ForEachScope(ProcessScope, sb);
 
-            static void ProcessScope(object scope, StringBuilder builder)
-                => builder.Append($"{scope}");
+            void ProcessScope(LogRecordScope scope, StringBuilder builder)
+            {
+                if (++scopeDepth > 0)
+                {
+                    builder.Append(", ");
+                }
+
+                builder.Append($"{scope.Scope}");
+            }
 
-            sb.Append($")");
+            sb.Append(')');
         }
 
         Console.WriteLine($"{this.name}.Export([{sb.ToString()}])");

examples/AspNetCore/Controllers/WeatherForecastController.cs

@@ -20,6 +20,7 @@
 using System.Net.Http;
 using Examples.AspNetCore.Models;
 using Microsoft.AspNetCore.Mvc;
+using Microsoft.Extensions.Logging;
 
 namespace Examples.AspNetCore.Controllers
 {
@@ -32,23 +33,39 @@ public class WeatherForecastController : ControllerBase
             "Freezing", "Bracing", "Chilly", "Cool", "Mild", "Warm", "Balmy", "Hot", "Sweltering", "Scorching",
         };
 
-        private static HttpClient httpClient = new HttpClient();
+        private static readonly HttpClient HttpClient = new HttpClient();
+
+        private readonly ILogger<WeatherForecastController> logger;
+
+        public WeatherForecastController(ILogger<WeatherForecastController> logger)
+        {
+            this.logger = logger ?? throw new ArgumentNullException(nameof(logger));
+        }
 
         [HttpGet]
         public IEnumerable<WeatherForecast> Get()
         {
+            using var scope = this.logger.BeginScope("{Id}", Guid.NewGuid().ToString("N"));
+
             // Making an http call here to serve as an example of
             // how dependency calls will be captured and treated
             // automatically as child of incoming request.
-            var res = httpClient.GetStringAsync("http://google.com").Result;
+            var res = HttpClient.GetStringAsync("http://google.com").Result;
             var rng = new Random();
-            return Enumerable.Range(1, 5).Select(index => new WeatherForecast
+            var forecast = Enumerable.Range(1, 5).Select(index => new WeatherForecast
             {
                 Date = DateTime.Now.AddDays(index),
                 TemperatureC = rng.Next(-20, 55),
                 Summary = Summaries[rng.Next(Summaries.Length)],
             })
             .ToArray();
+
+            this.logger.LogInformation(
+                "WeatherForecasts generated {count}: {forecasts}",
+                forecast.Length,
+                forecast);
+
+            return forecast;
         }
     }
 }

examples/AspNetCore/Program.cs

@@ -15,7 +15,10 @@
 // </copyright>
 
 using Microsoft.AspNetCore.Hosting;
+using Microsoft.Extensions.Configuration;
 using Microsoft.Extensions.Hosting;
+using Microsoft.Extensions.Logging;
+using OpenTelemetry.Logs;
 
 namespace Examples.AspNetCore
 {
@@ -31,6 +34,23 @@ public static IHostBuilder CreateHostBuilder(string[] args) =>
                 .ConfigureWebHostDefaults(webBuilder =>
                 {
                     webBuilder.UseStartup<Startup>();
+                })
+                .ConfigureLogging((context, builder) =>
+                {
+                    builder.ClearProviders();
+                    builder.AddConsole();
+
+                    var useLogging = context.Configuration.GetValue<bool>("UseLogging");
+                    if (useLogging)
+                    {
+                        builder.AddOpenTelemetry(options =>
+                        {
+                            options.IncludeScopes = true;
+                            options.ParseStateValues = true;
+                            options.IncludeFormattedMessage = true;
+                            options.AddConsoleExporter();
+                        });
+                    }
                 });
     }
 }

examples/AspNetCore/appsettings.json

@@ -8,6 +8,7 @@
   },
   "AllowedHosts": "*",
   "UseExporter": "console",
+  "UseLogging": true,
   "Jaeger": {
     "ServiceName": "jaeger-test",
     "AgentHost": "localhost",

src/OpenTelemetry.Exporter.Console/ConsoleLogRecordExporter.cs

@@ -16,6 +16,7 @@
 
 #if NET461 || NETSTANDARD2_0
 using System;
+using System.Collections.Generic;
 using OpenTelemetry.Logs;
 using OpenTelemetry.Resources;
 
@@ -64,10 +65,22 @@ public override ExportResult Export(in Batch<LogRecord> batch)
                     this.WriteLine($"{"LogRecord.Exception:".PadRight(RightPaddingLength)}{logRecord.Exception?.Message}");
                 }
 
+                int scopeDepth = -1;
+
                 logRecord.ForEachScope(ProcessScope, this);
 
-                static void ProcessScope(object scope, ConsoleLogRecordExporter exporter)
-                    => exporter.WriteLine($"{"LogRecord.Scope:".PadRight(RightPaddingLength)}{scope}");
+                void ProcessScope(LogRecordScope scope, ConsoleLogRecordExporter exporter)
+                {
+                    if (++scopeDepth == 0)
+                    {
+                        exporter.WriteLine("LogRecord.ScopeValues (Key:Value):");
+                    }
+
+                    foreach (KeyValuePair<string, object> scopeItem in scope)
+                    {
+                        exporter.WriteLine($"[Scope.{scopeDepth}]:{scopeItem.Key.PadRight(RightPaddingLength)}{scopeItem.Value}");
+                    }
+                }
 
                 var resource = this.ParentProvider.GetResource();
                 if (resource != Resource.Empty)

src/OpenTelemetry/.publicApi/net461/PublicAPI.Unshipped.txt

@@ -1,6 +1,17 @@
-OpenTelemetry.Logs.LogRecord.ForEachScope<TState>(System.Action<object, TState> callback, TState state) -> void
+OpenTelemetry.Logs.LogRecord.ForEachScope<TState>(System.Action<OpenTelemetry.Logs.LogRecordScope, TState> callback, TState state) -> void
 OpenTelemetry.Logs.LogRecord.FormattedMessage.get -> string
 OpenTelemetry.Logs.LogRecord.StateValues.get -> System.Collections.Generic.IReadOnlyList<System.Collections.Generic.KeyValuePair<string, object>>
+OpenTelemetry.Logs.LogRecordScope
+OpenTelemetry.Logs.LogRecordScope.Enumerator
+OpenTelemetry.Logs.LogRecordScope.Enumerator.Current.get -> System.Collections.Generic.KeyValuePair<string, object>
+OpenTelemetry.Logs.LogRecordScope.Enumerator.Dispose() -> void
+OpenTelemetry.Logs.LogRecordScope.Enumerator.Enumerator() -> void
+OpenTelemetry.Logs.LogRecordScope.Enumerator.Enumerator(object scope) -> void
+OpenTelemetry.Logs.LogRecordScope.Enumerator.MoveNext() -> bool
+OpenTelemetry.Logs.LogRecordScope.Enumerator.Reset() -> void
+OpenTelemetry.Logs.LogRecordScope.GetEnumerator() -> OpenTelemetry.Logs.LogRecordScope.Enumerator
+OpenTelemetry.Logs.LogRecordScope.LogRecordScope() -> void
+OpenTelemetry.Logs.LogRecordScope.Scope.get -> object
 OpenTelemetry.Logs.OpenTelemetryLoggerOptions.IncludeFormattedMessage.get -> bool
 OpenTelemetry.Logs.OpenTelemetryLoggerOptions.IncludeFormattedMessage.set -> void
 OpenTelemetry.Logs.OpenTelemetryLoggerOptions.IncludeScopes.get -> bool
@@ -16,6 +27,7 @@ OpenTelemetry.Trace.TracerProviderBuilderBase
 OpenTelemetry.Trace.TracerProviderBuilderBase.AddInstrumentation(string instrumentationName, string instrumentationVersion, System.Func<object> instrumentationFactory) -> OpenTelemetry.Trace.TracerProviderBuilder
 OpenTelemetry.Trace.TracerProviderBuilderBase.Build() -> OpenTelemetry.Trace.TracerProvider
 OpenTelemetry.Trace.TracerProviderBuilderBase.TracerProviderBuilderBase() -> void
+override OpenTelemetry.BatchLogRecordExportProcessor.OnEnd(OpenTelemetry.Logs.LogRecord data) -> void
 override OpenTelemetry.Trace.TracerProviderBuilderBase.AddInstrumentation<TInstrumentation>(System.Func<TInstrumentation> instrumentationFactory) -> OpenTelemetry.Trace.TracerProviderBuilder
 override OpenTelemetry.Trace.TracerProviderBuilderBase.AddLegacySource(string operationName) -> OpenTelemetry.Trace.TracerProviderBuilder
 override OpenTelemetry.Trace.TracerProviderBuilderBase.AddSource(params string[] names) -> OpenTelemetry.Trace.TracerProviderBuilder

src/OpenTelemetry/.publicApi/netstandard2.0/PublicAPI.Unshipped.txt

@@ -1,6 +1,17 @@
-OpenTelemetry.Logs.LogRecord.ForEachScope<TState>(System.Action<object, TState> callback, TState state) -> void
+OpenTelemetry.Logs.LogRecord.ForEachScope<TState>(System.Action<OpenTelemetry.Logs.LogRecordScope, TState> callback, TState state) -> void
 OpenTelemetry.Logs.LogRecord.FormattedMessage.get -> string
 OpenTelemetry.Logs.LogRecord.StateValues.get -> System.Collections.Generic.IReadOnlyList<System.Collections.Generic.KeyValuePair<string, object>>
+OpenTelemetry.Logs.LogRecordScope
+OpenTelemetry.Logs.LogRecordScope.Enumerator
+OpenTelemetry.Logs.LogRecordScope.Enumerator.Current.get -> System.Collections.Generic.KeyValuePair<string, object>
+OpenTelemetry.Logs.LogRecordScope.Enumerator.Dispose() -> void
+OpenTelemetry.Logs.LogRecordScope.Enumerator.Enumerator() -> void
+OpenTelemetry.Logs.LogRecordScope.Enumerator.Enumerator(object scope) -> void
+OpenTelemetry.Logs.LogRecordScope.Enumerator.MoveNext() -> bool
+OpenTelemetry.Logs.LogRecordScope.Enumerator.Reset() -> void
+OpenTelemetry.Logs.LogRecordScope.GetEnumerator() -> OpenTelemetry.Logs.LogRecordScope.Enumerator
+OpenTelemetry.Logs.LogRecordScope.LogRecordScope() -> void
+OpenTelemetry.Logs.LogRecordScope.Scope.get -> object
 OpenTelemetry.Logs.OpenTelemetryLoggerOptions.IncludeFormattedMessage.get -> bool
 OpenTelemetry.Logs.OpenTelemetryLoggerOptions.IncludeFormattedMessage.set -> void
 OpenTelemetry.Logs.OpenTelemetryLoggerOptions.IncludeScopes.get -> bool
@@ -16,6 +27,7 @@ OpenTelemetry.Trace.TracerProviderBuilderBase
 OpenTelemetry.Trace.TracerProviderBuilderBase.AddInstrumentation(string instrumentationName, string instrumentationVersion, System.Func<object> instrumentationFactory) -> OpenTelemetry.Trace.TracerProviderBuilder
 OpenTelemetry.Trace.TracerProviderBuilderBase.Build() -> OpenTelemetry.Trace.TracerProvider
 OpenTelemetry.Trace.TracerProviderBuilderBase.TracerProviderBuilderBase() -> void
+override OpenTelemetry.BatchLogRecordExportProcessor.OnEnd(OpenTelemetry.Logs.LogRecord data) -> void
 override OpenTelemetry.Trace.TracerProviderBuilderBase.AddInstrumentation<TInstrumentation>(System.Func<TInstrumentation> instrumentationFactory) -> OpenTelemetry.Trace.TracerProviderBuilder
 override OpenTelemetry.Trace.TracerProviderBuilderBase.AddLegacySource(string operationName) -> OpenTelemetry.Trace.TracerProviderBuilder
 override OpenTelemetry.Trace.TracerProviderBuilderBase.AddSource(params string[] names) -> OpenTelemetry.Trace.TracerProviderBuilder

src/OpenTelemetry/BatchLogRecordExportProcessor.cs

@@ -35,6 +35,13 @@ public BatchLogRecordExportProcessor(
                 maxExportBatchSize)
         {
         }
+
+        public override void OnEnd(LogRecord data)
+        {
+            data.BufferLogScopes();
+
+            base.OnEnd(data);
+        }
     }
 }
 #endif

src/OpenTelemetry/CHANGELOG.md

@@ -13,6 +13,13 @@ please check the latest changes
   public API
   ([#2019](https://github.com/open-telemetry/opentelemetry-dotnet/pull/2019))
 
+* Fixed an issue causing inconsistent log scopes when using
+  `BatchLogRecordExportProcessor`. To make parsing scopes easier the
+  `LogRecord.ForEachScope` signature has been changed to receive instances of
+  `LogRecordScope` (a new type which implements
+  `IEnumerator<KeyValuePair<string, object>>` for accessing scope items)
+  ([#2026](https://github.com/open-telemetry/opentelemetry-dotnet/pull/2026))
+
 ## 1.1.0-beta2
 
 Released 2021-Apr-23

src/OpenTelemetry/Logs/LogRecord.cs

@@ -18,16 +18,22 @@
 using System;
 using System.Collections.Generic;
 using System.Diagnostics;
+using System.Runtime.CompilerServices;
 using Microsoft.Extensions.Logging;
 
 namespace OpenTelemetry.Logs
 {
     /// <summary>
-    /// Log record base class.
+    /// Stores details about a log message.
     /// </summary>
     public sealed class LogRecord
     {
-        private readonly IExternalScopeProvider scopeProvider;
+        private static readonly Action<object, List<object>> AddScopeToBufferedList = (object scope, List<object> state) =>
+        {
+            state.Add(scope);
+        };
+
+        private List<object> bufferedScopes;
 
         internal LogRecord(
             IExternalScopeProvider scopeProvider,
@@ -40,7 +46,7 @@ internal LogRecord(
             Exception exception,
             IReadOnlyList<KeyValuePair<string, object>> stateValues)
         {
-            this.scopeProvider = scopeProvider;
+            this.ScopeProvider = scopeProvider;
 
             var activity = Activity.Current;
             if (activity != null)
@@ -79,23 +85,92 @@ internal LogRecord(
 
         public string FormattedMessage { get; }
 
+        /// <summary>
+        /// Gets the raw state attached to the log. Set to <see
+        /// langword="null"/> when <see
+        /// cref="OpenTelemetryLoggerOptions.ParseStateValues"/> is enabled.
+        /// </summary>
         public object State { get; }
 
+        /// <summary>
+        /// Gets the parsed state values attached to the log. Set when <see
+        /// cref="OpenTelemetryLoggerOptions.ParseStateValues"/> is enabled
+        /// otherwise <see langword="null"/>.
+        /// </summary>
         public IReadOnlyList<KeyValuePair<string, object>> StateValues { get; }
 
         public Exception Exception { get; }
 
+        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
         /// this method.
         /// </summary>
+        /// <remarks>
+        /// Note: Scopes are only available during the lifecycle of the log
+        /// message being written. If you need to capture scopes to be used
+        /// later (for example in batching scenarios), call <see
+        /// cref="BufferLogScopes"/> to safely capture the values (incurs
+        /// allocation).
+        /// </remarks>
         /// <typeparam name="TState">State.</typeparam>
         /// <param name="callback">The callback to be executed for every scope object.</param>
         /// <param name="state">The state object to be passed into the callback.</param>
-        public void ForEachScope<TState>(Action<object, TState> callback, TState state)
+        public void ForEachScope<TState>(Action<LogRecordScope, TState> callback, TState state)
+        {
+            var forEachScopeState = new ScopeForEachState<TState>(callback, state);
+
+            if (this.bufferedScopes != null)
+            {
+                foreach (object scope in this.bufferedScopes)
+                {
+                    ScopeForEachState<TState>.ForEachScope(scope, forEachScopeState);
+                }
+            }
+            else if (this.ScopeProvider != null)
+            {
+                this.ScopeProvider.ForEachScope(ScopeForEachState<TState>.ForEachScope, forEachScopeState);
+            }
+        }
+
+        /// <summary>
+        /// Buffers the scopes attached to the log into a list so that they can
+        /// be safely processed after the log message lifecycle has ended.
+        /// </summary>
+        internal void BufferLogScopes()
+        {
+            if (this.ScopeProvider == null || this.bufferedScopes != null)
+            {
+                return;
+            }
+
+            List<object> scopes = new List<object>();
+
+            this.ScopeProvider?.ForEachScope(AddScopeToBufferedList, scopes);
+
+            this.bufferedScopes = scopes;
+        }
+
+        private readonly struct ScopeForEachState<TState>
         {
-            this.scopeProvider?.ForEachScope(callback, state);
+            public static readonly Action<object, ScopeForEachState<TState>> ForEachScope = (object scope, ScopeForEachState<TState> state) =>
+            {
+                LogRecordScope logRecordScope = new LogRecordScope(scope);
+
+                state.Callback(logRecordScope, state.UserState);
+            };
+
+            public readonly Action<LogRecordScope, TState> Callback;
+
+            public readonly TState UserState;
+
+            public ScopeForEachState(Action<LogRecordScope, TState> callback, TState state)
+            {
+                this.Callback = callback;
+                this.UserState = state;
+            }
         }
     }
 }