diff --git a/sdk/monitor/Azure.Monitor.OpenTelemetry.Exporter/CHANGELOG.md b/sdk/monitor/Azure.Monitor.OpenTelemetry.Exporter/CHANGELOG.md index 86b4c17399db5..30df46c5e3ccb 100644 --- a/sdk/monitor/Azure.Monitor.OpenTelemetry.Exporter/CHANGELOG.md +++ b/sdk/monitor/Azure.Monitor.OpenTelemetry.Exporter/CHANGELOG.md @@ -15,13 +15,30 @@ ### 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 conform to a + key-value pair structure. + ([#39453](https://github.com/Azure/azure-sdk-for-net/pull/39453)) + * **Previous Behavior**: Logging a scope with a statement like + `logger.BeginScope("SomeScopeValue")` would result in adding + 'SomeScopeValue' to the properties using a key that follows the pattern + 'scope->*'. Additionally, 'OriginalFormatScope_*' keys were used to handle + formatted strings within the scope. + * **New Behavior**: + * Non-key-value pair scopes are no longer added to the properties, + resulting in cleaner and more efficient log output. + * 'OriginalFormatScope_*' keys have been removed. + * In case of duplicate keys within the scopes, only the first entry is + retained, while all subsequent duplicate entries are discarded. ### Other Changes diff --git a/sdk/monitor/Azure.Monitor.OpenTelemetry.Exporter/src/Internals/Diagnostics/AzureMonitorExporterEventSource.cs b/sdk/monitor/Azure.Monitor.OpenTelemetry.Exporter/src/Internals/Diagnostics/AzureMonitorExporterEventSource.cs index a72f015fbcc1f..2b08e0405ecfa 100644 --- a/sdk/monitor/Azure.Monitor.OpenTelemetry.Exporter/src/Internals/Diagnostics/AzureMonitorExporterEventSource.cs +++ b/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 FailedToAddScopeItem(string key, Exception ex) + { + if (IsEnabled(EventLevel.Warning)) + { + FailedToAddScopeItem(key, ex.FlattenException().ToInvariantString()); + } + } + + [Event(40, Message = "An exception {1} occurred while adding the scope value associated with the key {0}", Level = EventLevel.Warning)] + public void FailedToAddScopeItem(string key, string exceptionMessage) => WriteEvent(40, key, exceptionMessage); + + [NonEvent] + public void FailedToAddLogAttribute(string key, Exception ex) + { + if (IsEnabled(EventLevel.Warning)) + { + FailedToAddLogAttribute(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 FailedToAddLogAttribute(string key, string exceptionMessage) => WriteEvent(41, key, exceptionMessage); } } diff --git a/sdk/monitor/Azure.Monitor.OpenTelemetry.Exporter/src/Internals/LogsHelper.cs b/sdk/monitor/Azure.Monitor.OpenTelemetry.Exporter/src/Internals/LogsHelper.cs index e64c3867cd72f..ed12e8d3776f6 100644 --- a/sdk/monitor/Azure.Monitor.OpenTelemetry.Exporter/src/Internals/LogsHelper.cs +++ b/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 s_depthCache = new ConcurrentDictionary(); - private static readonly Func s_convertDepthToStringRef = ConvertDepthToString; + private static readonly Action> s_processScope = (scope, properties) => + { + foreach (KeyValuePair scopeItem in scope) + { + if (string.IsNullOrEmpty(scopeItem.Key) || scopeItem.Key == "{OriginalFormat}") + { + continue; + } + + // Note: if Key exceeds MaxLength, the entire KVP will be dropped. + if (scopeItem.Key.Length <= SchemaConstants.MessageData_Properties_MaxKeyLength && scopeItem.Value != null) + { + try + { + if (!properties.ContainsKey(scopeItem.Key)) + { + properties.Add(scopeItem.Key, Convert.ToString(scopeItem.Value, CultureInfo.InvariantCulture)?.Truncate(SchemaConstants.MessageData_Properties_MaxValueLength)!); + } + } + catch (Exception ex) + { + AzureMonitorExporterEventSource.Log.FailedToAddScopeItem(scopeItem.Key, ex); + } + } + } + }; internal static List OtelToAzureMonitorLogs(Batch batchLogRecord, AzureMonitorResource? resource, string instrumentationKey) { @@ -69,28 +91,38 @@ internal static List OtelToAzureMonitorLogs(Batch batc foreach (KeyValuePair item in logRecord.Attributes ?? Enumerable.Empty>()) { - if (item.Key.Length <= SchemaConstants.KVP_MaxKeyLength && item.Value != null) + // Note: if Key exceeds MaxLength, the entire KVP will be dropped. + if (item.Key.Length <= SchemaConstants.MessageData_Properties_MaxKeyLength && item.Value != null) { - // Note: if Key exceeds MaxLength, the entire KVP will be dropped. - if (item.Key == "{OriginalFormat}") + try { - if (logRecord.Exception?.Message != null) + if (item.Key == "{OriginalFormat}") { - properties.Add("OriginalFormat", item.Value.ToString().Truncate(SchemaConstants.KVP_MaxValueLength) ?? "null"); + if (logRecord.Exception?.Message != null) + { + properties.Add("OriginalFormat", item.Value.ToString().Truncate(SchemaConstants.MessageData_Properties_MaxValueLength)!); + } + else if (message == null) + { + message = item.Value.ToString(); + } } - else if (message == null) + else { - message = item.Value.ToString(); + if (!properties.ContainsKey(item.Key)) + { + properties.Add(item.Key, item.Value.ToString().Truncate(SchemaConstants.MessageData_Properties_MaxValueLength)!); + } } } - else + catch (Exception ex) { - properties.Add(item.Key, item.Value.ToString().Truncate(SchemaConstants.KVP_MaxValueLength) ?? "null"); + AzureMonitorExporterEventSource.Log.FailedToAddLogAttribute(item.Key, ex); } } } - WriteScopeInformation(logRecord, properties); + logRecord.ForEachScope(s_processScope, properties); if (logRecord.EventId.Id != 0) { @@ -105,49 +137,6 @@ internal static List OtelToAzureMonitorLogs(Batch batc return message; } - internal static void WriteScopeInformation(LogRecord logRecord, IDictionary properties) - { - StringBuilder? builder = null; - int originalScopeDepth = 1; - logRecord.ForEachScope(ProcessScope, properties); - - void ProcessScope(LogRecordScope scope, IDictionary properties) - { - int valueDepth = 1; - foreach (KeyValuePair 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 +199,5 @@ internal static SeverityLevel GetSeverityLevel(LogLevel logLevel) return SeverityLevel.Verbose; } } - - private static string ConvertDepthToString(int depth) => $"{depth}"; } } diff --git a/sdk/monitor/Azure.Monitor.OpenTelemetry.Exporter/tests/Azure.Monitor.OpenTelemetry.Exporter.Tests/LogsHelperTests.cs b/sdk/monitor/Azure.Monitor.OpenTelemetry.Exporter/tests/Azure.Monitor.OpenTelemetry.Exporter.Tests/LogsHelperTests.cs index a781d69873f95..798db7e2f3f23 100644 --- a/sdk/monitor/Azure.Monitor.OpenTelemetry.Exporter/tests/Azure.Monitor.OpenTelemetry.Exporter.Tests/LogsHelperTests.cs +++ b/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(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> + { + new KeyValuePair(expectedScopeKey, expectedScopeValue), + })) + { + logger.LogInformation("Some log information message."); + } + + // Assert. + var logRecord = logRecords.Single(); + var properties = new ChangeTrackingDictionary(); + 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(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> + { + new KeyValuePair(expectedScopeKey, scopeValue), + })) + { + logger.LogInformation("Some log information message."); + } + + // Assert. + var logRecord = logRecords.Single(); + var properties = new ChangeTrackingDictionary(); + 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(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> + { + new KeyValuePair(expectedScopeKey, new CustomObject()), + new KeyValuePair(validScopeKey, validScopeValue), + })) + { + logger.LogInformation("Some log information message."); + } + + // Assert. + var logRecord = logRecords.Single(); + var properties = new ChangeTrackingDictionary(); + 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(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> + { + new KeyValuePair(expectedScopeKey, expectedScopeValue), + new KeyValuePair(expectedScopeKey, duplicateScopeValue), + })) + { + logger.LogInformation("Some log information message. {attributeKey} {attributeKey}.", expectedAttributeValue, duplicateAttributeValue); + } + + // Assert. + var logRecord = logRecords.Single(); + var properties = new ChangeTrackingDictionary(); + 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"); + } + } } }