Fixes for Log Scope Processing

sdk/monitor/Azure.Monitor.OpenTelemetry.Exporter/CHANGELOG.md

@@ -15,13 +15,24 @@
 ### Bugs Fixed
 
 * Fixed an issue during network failures which prevented the exporter to store
-the telemetry offline for retrying at a later time.
-([#38832](https://github.com/Azure/azure-sdk-for-net/pull/38832))
+  the telemetry offline for retrying at a later time.
+  ([#38832](https://github.com/Azure/azure-sdk-for-net/pull/38832))
 
 * Fixed an issue where `OriginalFormat` persisted in TraceTelemetry properties
-  with IncludeFormattedMessage enabled in OpenTelemetry LoggerProvider. This fix
-  prevents data duplication in message fields and properties.
+  with IncludeFormattedMessage set to true on [
+  OpenTelemetryLoggerOptions](https://github.com/open-telemetry/opentelemetry-dotnet/blob/main/src/OpenTelemetry/Logs/ILogger/OpenTelemetryLoggerOptions.cs)
+  of the OpenTelemetry LoggerProvider. This fix prevents data duplication in
+  message fields and properties.
   ([#39308](https://github.com/Azure/azure-sdk-for-net/pull/39308))
+
+* Fixed an issue related to the processing of scopes that do not adhere to a
+  key-value pair structure. Previously, when logging a scope using a statement
+  like `logger.BeginScope("SomeScopeValue")`, the value 'SomeScopeValue' would
+  be added to the properties with a key following the pattern
+  'OriginalFormatScope_*'. With this update, such non-key-value pair scopes are
+  no longer added to the properties, as they cannot be queried, resulting in
+  cleaner and more efficient log output.
+  ([#39453](https://github.com/Azure/azure-sdk-for-net/pull/39453))
 
 ### Other Changes
 

sdk/monitor/Azure.Monitor.OpenTelemetry.Exporter/src/Internals/Diagnostics/AzureMonitorExporterEventSource.cs

@@ -395,5 +395,29 @@ public void PartialContentResponseUnhandled(TelemetryErrorDetails error)
 
         [Event(39, Message = "Received a partial success from ingestion. This status code is not handled and telemetry will be lost. Error StatusCode: {0}. Error Message: {1}", Level = EventLevel.Warning)]
         public void PartialContentResponseUnhandled(string errorStatusCode, string errorMessage) => WriteEvent(39, errorStatusCode, errorMessage);
+
+        [NonEvent]
+        public void FailedToConvertScopeItem(string key, Exception ex)
+        {
+            if (IsEnabled(EventLevel.Warning))
+            {
+                FailedToConvertScopeItem(key, ex.FlattenException().ToInvariantString());
+            }
+        }
+
+        [Event(40, Message = "An exception {1} occurred while converting the scope value associated with the scope key {0}.", Level = EventLevel.Warning)]
+        public void FailedToConvertScopeItem(string key, string exceptionMessage) => WriteEvent(40, key, exceptionMessage);
+
+        [NonEvent]
+        public void FailedToConvertLogAttribute(string key, Exception ex)
+        {
+            if (IsEnabled(EventLevel.Warning))
+            {
+                FailedToConvertLogAttribute(key, ex.FlattenException().ToInvariantString());
+            }
+        }
+
+        [Event(41, Message = "An exception {1} occurred while adding the log attribute associated with the key {0}", Level = EventLevel.Warning)]
+        public void FailedToConvertLogAttribute(string key, string exceptionMessage) => WriteEvent(41, key, exceptionMessage);
     }
 }

sdk/monitor/Azure.Monitor.OpenTelemetry.Exporter/src/Internals/LogsHelper.cs

@@ -2,13 +2,11 @@
 // Licensed under the MIT License.
 
 using System;
-using System.Collections.Concurrent;
 using System.Collections.Generic;
 using System.Diagnostics;
 using System.Globalization;
 using System.Linq;
 using System.Reflection;
-using System.Text;
 using Azure.Monitor.OpenTelemetry.Exporter.Internals.Diagnostics;
 using Azure.Monitor.OpenTelemetry.Exporter.Models;
 
@@ -22,8 +20,32 @@ namespace Azure.Monitor.OpenTelemetry.Exporter.Internals
     internal static class LogsHelper
     {
         private const int Version = 2;
-        private static readonly ConcurrentDictionary<int, string> s_depthCache = new ConcurrentDictionary<int, string>();
-        private static readonly Func<int, string> s_convertDepthToStringRef = ConvertDepthToString;
+        private static readonly Action<LogRecordScope, IDictionary<string, string>> s_processScope = (scope, properties) =>
+        {
+            foreach (KeyValuePair<string, object?> scopeItem in scope)
+            {
+                if (string.IsNullOrEmpty(scopeItem.Key) || scopeItem.Key == "{OriginalFormat}")
+                {
+                    continue;
+                }
+
+                if (scopeItem.Value != null)
+                {
+                    try
+                    {
+                        string truncatedKey = scopeItem.Key.Truncate(SchemaConstants.MessageData_Properties_MaxKeyLength);
+                        if (!properties.ContainsKey(truncatedKey))
+                        {
+                            properties.Add(truncatedKey, Convert.ToString(scopeItem.Value, CultureInfo.InvariantCulture)?.Truncate(SchemaConstants.MessageData_Properties_MaxValueLength)!);
+                        }
+                    }
+                    catch (Exception ex)
+                    {
+                        AzureMonitorExporterEventSource.Log.FailedToConvertScopeItem(scopeItem.Key, ex);
+                    }
+                }
+            }
+        };
 
         internal static List<TelemetryItem> OtelToAzureMonitorLogs(Batch<LogRecord> batchLogRecord, AzureMonitorResource? resource, string instrumentationKey)
         {
@@ -85,12 +107,23 @@ internal static List<TelemetryItem> OtelToAzureMonitorLogs(Batch<LogRecord> batc
                     }
                     else
                     {
-                        properties.Add(item.Key, item.Value.ToString().Truncate(SchemaConstants.KVP_MaxValueLength) ?? "null");
+                        try
+                        {
+                            string truncatedKey = item.Key.Truncate(SchemaConstants.MessageData_Properties_MaxKeyLength);
+                            if (!properties.ContainsKey(truncatedKey))
+                            {
+                                properties.Add(item.Key, item.Value.ToString().Truncate(SchemaConstants.KVP_MaxValueLength)?.Truncate(SchemaConstants.MessageData_Properties_MaxValueLength)!);
+                            }
+                        }
+                        catch (Exception ex)
+                        {
+                            AzureMonitorExporterEventSource.Log.FailedToConvertLogAttribute(item.Key, ex);
+                        }
                     }
                 }
             }
 
-            WriteScopeInformation(logRecord, properties);
+            logRecord.ForEachScope(s_processScope, properties);
 
             if (logRecord.EventId.Id != 0)
             {
@@ -105,49 +138,6 @@ internal static List<TelemetryItem> OtelToAzureMonitorLogs(Batch<LogRecord> batc
             return message;
         }
 
-        internal static void WriteScopeInformation(LogRecord logRecord, IDictionary<string, string> properties)
-        {
-            StringBuilder? builder = null;
-            int originalScopeDepth = 1;
-            logRecord.ForEachScope(ProcessScope, properties);
-
-            void ProcessScope(LogRecordScope scope, IDictionary<string, string> properties)
-            {
-                int valueDepth = 1;
-                foreach (KeyValuePair<string, object?> scopeItem in scope)
-                {
-                    if (string.IsNullOrEmpty(scopeItem.Key))
-                    {
-                        builder ??= new StringBuilder();
-                        builder.Append(" => ").Append(scope.Scope);
-                    }
-                    else if (scopeItem.Key == "{OriginalFormat}")
-                    {
-                        properties.Add($"OriginalFormatScope_{s_depthCache.GetOrAdd(originalScopeDepth, s_convertDepthToStringRef)}",
-                                        Convert.ToString(scope.Scope, CultureInfo.InvariantCulture) ?? "null");
-                    }
-                    else if (!properties.TryGetValue(scopeItem.Key, out _))
-                    {
-                        properties.Add(scopeItem.Key,
-                                        Convert.ToString(scopeItem.Value, CultureInfo.InvariantCulture) ?? "null");
-                    }
-                    else
-                    {
-                        properties.Add($"{scopeItem.Key}_{s_depthCache.GetOrAdd(originalScopeDepth, s_convertDepthToStringRef)}_{s_depthCache.GetOrAdd(valueDepth, s_convertDepthToStringRef)}",
-                                        Convert.ToString(scopeItem.Value, CultureInfo.InvariantCulture) ?? "null");
-                        valueDepth++;
-                    }
-                }
-
-                originalScopeDepth++;
-            }
-
-            if (builder?.Length > 0)
-            {
-                properties.Add("Scope", builder.ToString().Truncate(SchemaConstants.KVP_MaxValueLength));
-            }
-        }
-
         internal static string GetProblemId(Exception exception)
         {
             string methodName = "UnknownMethod";
@@ -210,7 +200,5 @@ internal static SeverityLevel GetSeverityLevel(LogLevel logLevel)
                     return SeverityLevel.Verbose;
             }
         }
-
-        private static string ConvertDepthToString(int depth) => $"{depth}";
     }
 }

sdk/monitor/Azure.Monitor.OpenTelemetry.Exporter/tests/Azure.Monitor.OpenTelemetry.Exporter.Tests/LogsHelperTests.cs

@@ -3,7 +3,7 @@
 
 using System;
 using System.Collections.Generic;
-
+using System.Linq;
 using Azure.Core;
 using Azure.Monitor.OpenTelemetry.Exporter.Internals;
 using Azure.Monitor.OpenTelemetry.Exporter.Models;
@@ -232,5 +232,195 @@ public void ValidateTelemetryItem(string type)
             Assert.Equal(logResource.RoleName, telemetryItem[0].Tags[ContextTagKeys.AiCloudRole.ToString()]);
             Assert.Equal(logResource.RoleInstance, telemetryItem[0].Tags[ContextTagKeys.AiCloudRoleInstance.ToString()]);
         }
+
+        [Theory]
+        [InlineData(true)]
+        [InlineData(false)]
+        public void ValidateScopeHandlingInLogProcessing(bool includeScope)
+        {
+            // Arrange.
+            var logRecords = new List<LogRecord>(1);
+            using var loggerFactory = LoggerFactory.Create(builder =>
+            {
+                builder.AddOpenTelemetry(options =>
+                {
+                    options.IncludeScopes = includeScope;
+                    options.AddInMemoryExporter(logRecords);
+                });
+            });
+
+            var logger = loggerFactory.CreateLogger("Some category");
+
+            const string expectedScopeKey = "Some scope key";
+            const string expectedScopeValue = "Some scope value";
+
+            // Act.
+            using (logger.BeginScope(new List<KeyValuePair<string, object>>
+            {
+                new KeyValuePair<string, object>(expectedScopeKey, expectedScopeValue),
+            }))
+            {
+                logger.LogInformation("Some log information message.");
+            }
+
+            // Assert.
+            var logRecord = logRecords.Single();
+            var properties = new ChangeTrackingDictionary<string, string>();
+            LogsHelper.GetMessageAndSetProperties(logRecords[0], properties);
+
+            if (includeScope)
+            {
+                Assert.True(properties.TryGetValue(expectedScopeKey, out string actualScopeValue));
+                Assert.Equal(expectedScopeValue, actualScopeValue);
+            }
+            else
+            {
+                Assert.False(properties.TryGetValue(expectedScopeKey, out string actualScopeValue));
+            }
+        }
+
+        [Theory]
+        [InlineData("Some scope value")]
+        [InlineData('a')]
+        [InlineData(123)]
+        [InlineData(12.34)]
+        [InlineData(null)]
+        public void VerifyHandlingOfVariousScopeDataTypes(object scopeValue)
+        {
+            // Arrange.
+            var logRecords = new List<LogRecord>(1);
+            using var loggerFactory = LoggerFactory.Create(builder =>
+            {
+                builder.AddOpenTelemetry(options =>
+                {
+                    options.IncludeScopes = true;
+                    options.AddInMemoryExporter(logRecords);
+                });
+            });
+
+            var logger = loggerFactory.CreateLogger("Some category");
+
+            const string expectedScopeKey = "Some scope key";
+
+            // Act.
+            using (logger.BeginScope(new List<KeyValuePair<string, object>>
+            {
+                new KeyValuePair<string, object>(expectedScopeKey, scopeValue),
+            }))
+            {
+                logger.LogInformation("Some log information message.");
+            }
+
+            // Assert.
+            var logRecord = logRecords.Single();
+            var properties = new ChangeTrackingDictionary<string, string>();
+            LogsHelper.GetMessageAndSetProperties(logRecords[0], properties);
+
+            if (scopeValue != null)
+            {
+                Assert.Single(properties); // Assert that there is exactly one property
+                Assert.True(properties.TryGetValue(expectedScopeKey, out string actualScopeValue));
+                Assert.Equal(scopeValue.ToString(), actualScopeValue);
+            }
+            else
+            {
+                Assert.Empty(properties); // Assert that properties are empty
+            }
+        }
+
+        [Fact]
+        public void LogScope_WhenToStringOnCustomObjectThrows_ShouldStillProcessValidScopeItems()
+        {
+            // Arrange.
+            var logRecords = new List<LogRecord>(1);
+            using var loggerFactory = LoggerFactory.Create(builder =>
+            {
+                builder.AddOpenTelemetry(options =>
+                {
+                    options.IncludeScopes = true;
+                    options.IncludeFormattedMessage = true;
+                    options.AddInMemoryExporter(logRecords);
+                });
+            });
+
+            var logger = loggerFactory.CreateLogger("Some category");
+
+            const string expectedScopeKey = "Some scope key";
+            const string validScopeKey = "Valid key";
+            const string validScopeValue = "Valid value";
+
+            // Act.
+            using (logger.BeginScope(new List<KeyValuePair<string, object>>
+            {
+                new KeyValuePair<string, object>(expectedScopeKey, new CustomObject()),
+                new KeyValuePair<string, object>(validScopeKey, validScopeValue),
+            }))
+            {
+                logger.LogInformation("Some log information message.");
+            }
+
+            // Assert.
+            var logRecord = logRecords.Single();
+            var properties = new ChangeTrackingDictionary<string, string>();
+            LogsHelper.GetMessageAndSetProperties(logRecords[0], properties);
+
+            Assert.False(properties.ContainsKey(expectedScopeKey), "Properties should not contain the key of the CustomObject that threw an exception");
+            Assert.True(properties.ContainsKey(validScopeKey), "Properties should contain the key of the valid scope item.");
+            Assert.Equal(validScopeValue, properties[validScopeKey]);
+            Assert.Equal("Some log information message.", logRecords[0].FormattedMessage);
+        }
+
+        [Fact]
+        public void DuplicateKeysInLogRecordAttributesAndLogScope()
+        {
+            // Arrange.
+            var logRecords = new List<LogRecord>(1);
+            using var loggerFactory = LoggerFactory.Create(builder =>
+            {
+                builder.AddOpenTelemetry(options =>
+                {
+                    options.IncludeScopes = true;
+                    options.AddInMemoryExporter(logRecords);
+                });
+            });
+
+            var logger = loggerFactory.CreateLogger("Some category");
+
+            const string expectedScopeKey = "Some scope key";
+            const string expectedScopeValue = "Some scope value";
+            const string duplicateScopeValue = "Some duplicate scope value";
+
+            const string expectedAttributeValue = "Some attribute value";
+            const string duplicateAttributeValue = "Some duplicate attribute value";
+
+            // Act.
+            using (logger.BeginScope(new List<KeyValuePair<string, object>>
+            {
+                new KeyValuePair<string, object>(expectedScopeKey, expectedScopeValue),
+                new KeyValuePair<string, object>(expectedScopeKey, duplicateScopeValue),
+            }))
+            {
+                logger.LogInformation("Some log information message. {attributeKey} {attributeKey}.", expectedAttributeValue, duplicateAttributeValue);
+            }
+
+            // Assert.
+            var logRecord = logRecords.Single();
+            var properties = new ChangeTrackingDictionary<string, string>();
+            LogsHelper.GetMessageAndSetProperties(logRecords[0], properties);
+
+            Assert.Equal(2, properties.Count);
+            Assert.True(properties.TryGetValue(expectedScopeKey, out string actualScopeValue));
+            Assert.Equal(expectedScopeValue, actualScopeValue);
+            Assert.True(properties.TryGetValue("attributeKey", out string actualAttributeValue));
+            Assert.Equal(expectedAttributeValue, actualAttributeValue);
+        }
+
+        private class CustomObject
+        {
+            public override string ToString()
+            {
+                throw new InvalidOperationException("Custom exception in ToString method");
+            }
+        }
     }
 }