From 8d7472fd8de0be15fe120c5152d67883ff0f1881 Mon Sep 17 00:00:00 2001 From: John Crim Date: Wed, 26 Jun 2024 19:59:20 -0700 Subject: [PATCH 1/4] fix(telemetry transmission): Include ILogger CategoryName in logger output Previously this field was omitted, which was not consistent with normal ILogger behavior, or with Application Insights classic behavior. fixes: #44746 --- .../src/Internals/LogsHelper.cs | 6 +++ .../E2ETelemetryItemValidation/LogsTests.cs | 2 +- .../LogsHelperTests.cs | 42 +++++++++++++++---- .../MessageDataTests.cs | 2 +- 4 files changed, 42 insertions(+), 10 deletions(-) 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 2892fbec5edfd..fadb7b70e3374 100644 --- a/sdk/monitor/Azure.Monitor.OpenTelemetry.Exporter/src/Internals/LogsHelper.cs +++ b/sdk/monitor/Azure.Monitor.OpenTelemetry.Exporter/src/Internals/LogsHelper.cs @@ -124,6 +124,12 @@ internal static List OtelToAzureMonitorLogs(Batch batc logRecord.ForEachScope(s_processScope, properties); + var categoryName = logRecord.CategoryName; + if (!string.IsNullOrEmpty(categoryName)) + { + properties.Add("CategoryName", categoryName.Truncate(SchemaConstants.KVP_MaxValueLength)!); + } + if (logRecord.EventId.Id != 0) { properties.Add("EventId", logRecord.EventId.Id.ToString(CultureInfo.InvariantCulture)); diff --git a/sdk/monitor/Azure.Monitor.OpenTelemetry.Exporter/tests/Azure.Monitor.OpenTelemetry.Exporter.Tests/E2ETelemetryItemValidation/LogsTests.cs b/sdk/monitor/Azure.Monitor.OpenTelemetry.Exporter/tests/Azure.Monitor.OpenTelemetry.Exporter.Tests/E2ETelemetryItemValidation/LogsTests.cs index cb95fd64e3388..437390eed8258 100644 --- a/sdk/monitor/Azure.Monitor.OpenTelemetry.Exporter/tests/Azure.Monitor.OpenTelemetry.Exporter.Tests/E2ETelemetryItemValidation/LogsTests.cs +++ b/sdk/monitor/Azure.Monitor.OpenTelemetry.Exporter/tests/Azure.Monitor.OpenTelemetry.Exporter.Tests/E2ETelemetryItemValidation/LogsTests.cs @@ -83,7 +83,7 @@ public void VerifyLog(LogLevel logLevel, string expectedSeverityLevel) telemetryItem: telemetryItem!, expectedSeverityLevel: expectedSeverityLevel, expectedMessage: "Hello {name}.", - expectedMessageProperties: new Dictionary { { "name", "World" }}, + expectedMessageProperties: new Dictionary { { "name", "World" }, { "CategoryName", logCategoryName } }, expectedSpanId: null, expectedTraceId: null); } 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 3905ea097d64f..a86e52a02dadc 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 @@ -61,7 +61,7 @@ public void MessageIsSetToExceptionMessage(bool parseStateValues) Assert.Equal("tomato", name); Assert.True(properties.TryGetValue("price", out string price)); Assert.Equal("2.99", price); - Assert.Equal(3, properties.Count); + Assert.Equal(4, properties.Count); } [Fact] @@ -91,7 +91,7 @@ public void MessageIsSetToFormattedMessageWhenIncludeFormattedMessageIsSet() Assert.Equal("tomato", name); Assert.True(properties.TryGetValue("price", out string price)); Assert.Equal("2.99", price); - Assert.Equal(2, properties.Count); + Assert.Equal(3, properties.Count); } [Fact] @@ -121,7 +121,7 @@ public void MessageIsSetToOriginalFormatWhenIncludeFormattedMessageIsNotSet() Assert.Equal("tomato", name); Assert.True(properties.TryGetValue("price", out string price)); Assert.Equal("2.99", price); - Assert.Equal(2, properties.Count); + Assert.Equal(3, properties.Count); } [Theory] @@ -152,7 +152,7 @@ public void PropertiesContainFieldsFromStructuredLogs(bool parseStateValues) Assert.Equal("tomato", name); Assert.True(properties.TryGetValue("price", out string price)); Assert.Equal("2.99", price); - Assert.Equal(2, properties.Count); + Assert.Equal(3, properties.Count); } [Fact] @@ -180,7 +180,33 @@ public void PropertiesContainEventIdAndEventNameIfSetOnLog() Assert.Equal("1", eventId); Assert.True(properties.TryGetValue("EventName", out string eventName)); Assert.Equal("TestEvent", eventName); - Assert.Equal(2, properties.Count); + Assert.Equal(3, properties.Count); + } + + [Fact] + public void PropertiesContainLoggerName() + { + var logRecords = new List(); + using var loggerFactory = LoggerFactory.Create(builder => + { + builder.AddOpenTelemetry(options => + { + options.AddInMemoryExporter(logRecords); + }); + builder.AddFilter(typeof(LogsHelperTests).FullName, LogLevel.Trace); + }); + + var categoryName = nameof(LogsHelperTests); + var logger = loggerFactory.CreateLogger(categoryName); + + logger.LogInformation("Information goes here"); + + var properties = new ChangeTrackingDictionary(); + LogsHelper.GetMessageAndSetProperties(logRecords[0], properties); + + Assert.True(properties.TryGetValue("CategoryName", out string loggedCategoryName)); + Assert.Equal(categoryName, loggedCategoryName); + Assert.Single(properties); } [Fact] @@ -318,13 +344,13 @@ public void VerifyHandlingOfVariousScopeDataTypes(object scopeValue) if (scopeValue != null) { - Assert.Single(properties); // Assert that there is exactly one property + Assert.Equal(2, properties.Count); // Scope property + CategoryName Assert.True(properties.TryGetValue(expectedScopeKey, out string actualScopeValue)); Assert.Equal(scopeValue.ToString(), actualScopeValue); } else { - Assert.Empty(properties); // Assert that properties are empty + Assert.Single(properties); // Single property expected (CategoryName) } } @@ -408,7 +434,7 @@ public void DuplicateKeysInLogRecordAttributesAndLogScope() var properties = new ChangeTrackingDictionary(); LogsHelper.GetMessageAndSetProperties(logRecords[0], properties); - Assert.Equal(2, properties.Count); + Assert.Equal(3, properties.Count); Assert.True(properties.TryGetValue(expectedScopeKey, out string actualScopeValue)); Assert.Equal(expectedScopeValue, actualScopeValue); Assert.True(properties.TryGetValue("attributeKey", out string actualAttributeValue)); diff --git a/sdk/monitor/Azure.Monitor.OpenTelemetry.Exporter/tests/Azure.Monitor.OpenTelemetry.Exporter.Tests/MessageDataTests.cs b/sdk/monitor/Azure.Monitor.OpenTelemetry.Exporter/tests/Azure.Monitor.OpenTelemetry.Exporter.Tests/MessageDataTests.cs index ebeacb8c1d83b..a26f8d7da911f 100644 --- a/sdk/monitor/Azure.Monitor.OpenTelemetry.Exporter/tests/Azure.Monitor.OpenTelemetry.Exporter.Tests/MessageDataTests.cs +++ b/sdk/monitor/Azure.Monitor.OpenTelemetry.Exporter/tests/Azure.Monitor.OpenTelemetry.Exporter.Tests/MessageDataTests.cs @@ -41,7 +41,7 @@ public void ValidateMessageData(LogLevel logLevel) Assert.Equal("Log Message", messageData.Message); Assert.Equal(LogsHelper.GetSeverityLevel(logLevel), messageData.SeverityLevel); - Assert.Empty(messageData.Properties); + Assert.Single(messageData.Properties); // CategoryName property expected Assert.Empty(messageData.Measurements); } } From fd30647264c8db722229ebccbb0ebc14bebf2aaf Mon Sep 17 00:00:00 2001 From: John Crim Date: Wed, 26 Jun 2024 22:35:52 -0700 Subject: [PATCH 2/4] improve(otel exporter tests): Verify that logger CategoryName is in Exception log entries --- .../LogsHelperTests.cs | 34 ++++++++++++++++++- 1 file changed, 33 insertions(+), 1 deletion(-) 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 a86e52a02dadc..651b6fa2d0225 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 @@ -184,7 +184,7 @@ public void PropertiesContainEventIdAndEventNameIfSetOnLog() } [Fact] - public void PropertiesContainLoggerName() + public void PropertiesContainLoggerCategoryName() { var logRecords = new List(); using var loggerFactory = LoggerFactory.Create(builder => @@ -209,6 +209,38 @@ public void PropertiesContainLoggerName() Assert.Single(properties); } + [Fact] + public void ExceptionPropertiesContainLoggerCategoryName() + { + var logRecords = new List(); + using var loggerFactory = LoggerFactory.Create(builder => + { + builder.AddOpenTelemetry(options => + { + options.AddInMemoryExporter(logRecords); + }); + builder.AddFilter(typeof(LogsHelperTests).FullName, LogLevel.Trace); + }); + + var logger = loggerFactory.CreateLogger(); + try + { + throw new Exception("Test Exception"); + } + catch (Exception ex) + { + logger.LogError(ex, "Here's an error"); + } + + var properties = new ChangeTrackingDictionary(); + var message = LogsHelper.GetMessageAndSetProperties(logRecords[0], properties); + + Assert.Equal("Test Exception", message); + + Assert.True(properties.TryGetValue("CategoryName", out string categoryName)); + Assert.EndsWith(nameof(LogsHelperTests), categoryName); + } + [Fact] public void ValidateSeverityLevels() { From 244610eff388e6b419c5e261a3dbca23ed49c49e Mon Sep 17 00:00:00 2001 From: John Crim Date: Fri, 12 Jul 2024 12:02:47 -0700 Subject: [PATCH 3/4] improve(live metrics): Include LogRecord.CategoryName in live metrics It's included in live metrics using app insights classic, so should be included here too. --- .../LiveMetrics/DataCollection/DocumentHelper.cs | 14 ++++++++++++++ .../LiveMetrics/DocumentTests/DocumentTestBase.cs | 9 +++++---- .../LiveMetrics/DocumentTests/LogTests.cs | 8 ++++++-- 3 files changed, 25 insertions(+), 6 deletions(-) diff --git a/sdk/monitor/Azure.Monitor.OpenTelemetry.AspNetCore/src/LiveMetrics/DataCollection/DocumentHelper.cs b/sdk/monitor/Azure.Monitor.OpenTelemetry.AspNetCore/src/LiveMetrics/DataCollection/DocumentHelper.cs index 66a896927b929..c4727d0dbc4bb 100644 --- a/sdk/monitor/Azure.Monitor.OpenTelemetry.AspNetCore/src/LiveMetrics/DataCollection/DocumentHelper.cs +++ b/sdk/monitor/Azure.Monitor.OpenTelemetry.AspNetCore/src/LiveMetrics/DataCollection/DocumentHelper.cs @@ -293,6 +293,13 @@ internal static ExceptionDocument ConvertToExceptionDocument(LogRecord logRecord int propertiesCount = 0; + var categoryName = logRecord.CategoryName; + if (!string.IsNullOrEmpty(categoryName)) + { + exceptionDocument.Properties.Add(new KeyValuePairString("CategoryName", categoryName)); + propertiesCount++; + } + foreach (KeyValuePair item in logRecord.Attributes ?? Enumerable.Empty>()) { if (item.Value != null && item.Key != "{OriginalFormat}") @@ -319,6 +326,13 @@ internal static Models.Trace ConvertToLogDocument(LogRecord logRecord) int propertiesCount = 0; + var categoryName = logRecord.CategoryName; + if (!string.IsNullOrEmpty(categoryName)) + { + traceDocument.Properties.Add(new KeyValuePairString("CategoryName", categoryName)); + propertiesCount++; + } + foreach (KeyValuePair item in logRecord.Attributes ?? Enumerable.Empty>()) { if (item.Value != null && item.Key != "{OriginalFormat}") diff --git a/sdk/monitor/Azure.Monitor.OpenTelemetry.AspNetCore/tests/Azure.Monitor.OpenTelemetry.AspNetCore.Tests/LiveMetrics/DocumentTests/DocumentTestBase.cs b/sdk/monitor/Azure.Monitor.OpenTelemetry.AspNetCore/tests/Azure.Monitor.OpenTelemetry.AspNetCore.Tests/LiveMetrics/DocumentTests/DocumentTestBase.cs index 0bfd50a283c6e..ea9416985da46 100644 --- a/sdk/monitor/Azure.Monitor.OpenTelemetry.AspNetCore/tests/Azure.Monitor.OpenTelemetry.AspNetCore.Tests/LiveMetrics/DocumentTests/DocumentTestBase.cs +++ b/sdk/monitor/Azure.Monitor.OpenTelemetry.AspNetCore/tests/Azure.Monitor.OpenTelemetry.AspNetCore.Tests/LiveMetrics/DocumentTests/DocumentTestBase.cs @@ -55,17 +55,18 @@ internal void PrintActivity(Activity activity) } } - internal void VerifyCustomProperties(DocumentIngress document) + internal void VerifyCustomProperties(DocumentIngress document, int reservedPropertyCount = 0) { Assert.Equal(10, document.Properties.Count); - for (int i = 1; i <= 10; i++) + for (int i = 1; i <= (10 - reservedPropertyCount); i++) { Assert.Contains(document.Properties, x => x.Key == $"customKey{i}" && x.Value == $"customValue{i}"); } - // LiveMetrics supports a maximum of 10 Properties. #11 should not be included. - Assert.DoesNotContain(document.Properties, x => x.Key == $"customKey11" && x.Value == $"customValue11"); + // LiveMetrics supports a maximum of 10 Properties; reservedPropertyCount is the count of properties taken up by standard properties + int firstOmittedPropertyIndex = 11 - reservedPropertyCount; + Assert.DoesNotContain(document.Properties, x => x.Key == $"customKey{ firstOmittedPropertyIndex }" && x.Value == $"customValue{ firstOmittedPropertyIndex }"); } } } diff --git a/sdk/monitor/Azure.Monitor.OpenTelemetry.AspNetCore/tests/Azure.Monitor.OpenTelemetry.AspNetCore.Tests/LiveMetrics/DocumentTests/LogTests.cs b/sdk/monitor/Azure.Monitor.OpenTelemetry.AspNetCore/tests/Azure.Monitor.OpenTelemetry.AspNetCore.Tests/LiveMetrics/DocumentTests/LogTests.cs index 1a94807612bdd..c458e9a312102 100644 --- a/sdk/monitor/Azure.Monitor.OpenTelemetry.AspNetCore/tests/Azure.Monitor.OpenTelemetry.AspNetCore.Tests/LiveMetrics/DocumentTests/LogTests.cs +++ b/sdk/monitor/Azure.Monitor.OpenTelemetry.AspNetCore/tests/Azure.Monitor.OpenTelemetry.AspNetCore.Tests/LiveMetrics/DocumentTests/LogTests.cs @@ -66,7 +66,9 @@ public void VerifyLogRecord(bool formatMessage) Assert.Equal("Hello {customKey1} {customKey2} {customKey3} {customKey4} {customKey5} {customKey6} {customKey7} {customKey8} {customKey9} {customKey10} {customKey11}.", logDocument.Message); } - VerifyCustomProperties(logDocument); + Assert.Equal(logCategoryName, logDocument.Properties.First(p => p.Key == "CategoryName").Value); + + VerifyCustomProperties(logDocument, 1); Assert.DoesNotContain(logDocument.Properties, x => x.Key == "{OriginalFormat}"); // The following "EXTENSION" properties are used to calculate metrics. These are not serialized. @@ -123,7 +125,9 @@ public void VerifyLogRecordWithException() Assert.Equal(typeof(System.Exception).FullName, exceptionDocument.ExceptionType); Assert.Equal("Test exception", exceptionDocument.ExceptionMessage); - VerifyCustomProperties(exceptionDocument); + Assert.Equal(logCategoryName, exceptionDocument.Properties.First(p => p.Key == "CategoryName").Value); + + VerifyCustomProperties(exceptionDocument, 1); Assert.DoesNotContain(exceptionDocument.Properties, x => x.Key == "{OriginalFormat}"); // The following "EXTENSION" properties are used to calculate metrics. These are not serialized. From dac061dfaea45ca071d2db7a8b31af6ae8f452ce Mon Sep 17 00:00:00 2001 From: John Crim Date: Fri, 12 Jul 2024 15:06:37 -0700 Subject: [PATCH 4/4] docs(changelog): Update changelog with "add CategoryName" info --- .../CHANGELOG.md | 5 +++++ .../CHANGELOG.md | 13 +++++++++---- 2 files changed, 14 insertions(+), 4 deletions(-) diff --git a/sdk/monitor/Azure.Monitor.OpenTelemetry.AspNetCore/CHANGELOG.md b/sdk/monitor/Azure.Monitor.OpenTelemetry.AspNetCore/CHANGELOG.md index 5b95067073513..1bf35679963d8 100644 --- a/sdk/monitor/Azure.Monitor.OpenTelemetry.AspNetCore/CHANGELOG.md +++ b/sdk/monitor/Azure.Monitor.OpenTelemetry.AspNetCore/CHANGELOG.md @@ -8,6 +8,11 @@ ### Bugs Fixed +* Added the `LogRecord.CategoryName` field to log and exception telemetry. + Previously the `CategoryName` field was omitted, which was inconsistent with + expected `ILogger` behavior, and with Application Insights classic behavior. + ([#44754](https://github.com/Azure/azure-sdk-for-net/pull/44754)) + * Fixed an issue where a `DuplicateKeyException` could be thrown if `EventId` and `EventName` were present in both `LogRecord` (`LogRecord.EventId`, `LogRecord.EventName`) and `LogRecord.Attributes`. The method now uses diff --git a/sdk/monitor/Azure.Monitor.OpenTelemetry.Exporter/CHANGELOG.md b/sdk/monitor/Azure.Monitor.OpenTelemetry.Exporter/CHANGELOG.md index de3dfaa4bcbb0..8942b94900478 100644 --- a/sdk/monitor/Azure.Monitor.OpenTelemetry.Exporter/CHANGELOG.md +++ b/sdk/monitor/Azure.Monitor.OpenTelemetry.Exporter/CHANGELOG.md @@ -8,6 +8,11 @@ ### Bugs Fixed +* Added the `LogRecord.CategoryName` field to log and exception telemetry. + Previously the `CategoryName` field was omitted, which was inconsistent with + expected `ILogger` behavior, and with Application Insights classic behavior. + ([#44754](https://github.com/Azure/azure-sdk-for-net/pull/44754)) + ### Features Added * Added `LoggerProviderBuilder.AddAzureMonitorLogExporter` registration extension. @@ -96,7 +101,7 @@ 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)) @@ -105,7 +110,7 @@ '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**: + * **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. @@ -189,7 +194,7 @@ ([#36509](https://github.com/Azure/azure-sdk-for-net/pull/36509)) * Add `db.name` to custom properties. ([#36389](https://github.com/Azure/azure-sdk-for-net/pull/36389)) - + ### Bugs Fixed * Fixed an issue which resulted in standard metrics getting exported to backends other than Azure Monitor, when Azure Monitor metric exporter was used with other exporters such as otlp side by side. @@ -318,7 +323,7 @@ * Request and Dependency Success criteria will now be decided based on `Activity.Status` ([#31024](https://github.com/Azure/azure-sdk-for-net/pull/31024)) * Changed `AzureMonitorTraceExporter` to internal ([#31067](https://github.com/Azure/azure-sdk-for-net/pull/31067)) - + ### Bugs Fixed * Fix shared RoleName/RoleInstance between Trace and Log Exporter ([#26438](https://github.com/Azure/azure-sdk-for-net/pull/26438))