Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

fix(otel logging): Include ILogger CategoryName in logger output #44754

Merged
merged 6 commits into from
Jul 12, 2024
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -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<string, object?> item in logRecord.Attributes ?? Enumerable.Empty<KeyValuePair<string, object?>>())
{
if (item.Value != null && item.Key != "{OriginalFormat}")
Expand All @@ -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<string, object?> item in logRecord.Attributes ?? Enumerable.Empty<KeyValuePair<string, object?>>())
{
if (item.Value != null && item.Key != "{OriginalFormat}")
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -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 }");
}
}
}
Original file line number Diff line number Diff line change
Expand Up @@ -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.
Expand Down Expand Up @@ -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.
Expand Down
13 changes: 9 additions & 4 deletions sdk/monitor/Azure.Monitor.OpenTelemetry.Exporter/CHANGELOG.md
Original file line number Diff line number Diff line change
Expand Up @@ -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.
Expand Down Expand Up @@ -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))
Expand All @@ -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.
Expand Down Expand Up @@ -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.
Expand Down Expand Up @@ -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))
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -124,6 +124,12 @@ internal static List<TelemetryItem> OtelToAzureMonitorLogs(Batch<LogRecord> batc

logRecord.ForEachScope(s_processScope, properties);

var categoryName = logRecord.CategoryName;
if (!properties.ContainsKey("CategoryName") && !string.IsNullOrEmpty(categoryName))
{
properties.Add("CategoryName", categoryName.Truncate(SchemaConstants.KVP_MaxValueLength)!);
cijothomas marked this conversation as resolved.
Show resolved Hide resolved
}

if (!properties.ContainsKey("EventId") && logRecord.EventId.Id != 0)
{
properties.Add("EventId", logRecord.EventId.Id.ToString(CultureInfo.InvariantCulture));
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -83,7 +83,7 @@ public void VerifyLog(LogLevel logLevel, string expectedSeverityLevel)
telemetryItem: telemetryItem!,
expectedSeverityLevel: expectedSeverityLevel,
expectedMessage: "Hello {name}.",
expectedMessageProperties: new Dictionary<string, string> { { "EventId", "1" }, { "name", "World" }},
expectedMessageProperties: new Dictionary<string, string> { { "EventId", "1" }, { "name", "World" }, { "CategoryName", logCategoryName } },
expectedSpanId: null,
expectedTraceId: null);
}
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -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]
Expand Down Expand Up @@ -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]
Expand Down Expand Up @@ -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]
Expand Down Expand Up @@ -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]
Expand Down Expand Up @@ -180,7 +180,65 @@ 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 PropertiesContainLoggerCategoryName()
{
var logRecords = new List<LogRecord>();
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<string, string>();
LogsHelper.GetMessageAndSetProperties(logRecords[0], properties);

Assert.True(properties.TryGetValue("CategoryName", out string loggedCategoryName));
Assert.Equal(categoryName, loggedCategoryName);
Assert.Single(properties);
}

[Fact]
public void ExceptionPropertiesContainLoggerCategoryName()
{
var logRecords = new List<LogRecord>();
using var loggerFactory = LoggerFactory.Create(builder =>
{
builder.AddOpenTelemetry(options =>
{
options.AddInMemoryExporter(logRecords);
});
builder.AddFilter(typeof(LogsHelperTests).FullName, LogLevel.Trace);
});

var logger = loggerFactory.CreateLogger<LogsHelperTests>();
try
{
throw new Exception("Test Exception");
}
catch (Exception ex)
{
logger.LogError(ex, "Here's an error");
}

var properties = new ChangeTrackingDictionary<string, string>();
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]
Expand Down Expand Up @@ -210,7 +268,7 @@ public void LogRecordAndAttributesContainEventIdAndEventName()
Assert.Equal("100", eventId);
Assert.True(properties.TryGetValue("EventName", out string eventName));
Assert.Equal("TestAttributeEventName", eventName);
Assert.Equal(2, properties.Count);
Assert.Equal(3, properties.Count);
}

[Fact]
Expand Down Expand Up @@ -348,13 +406,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)
}
}

Expand Down Expand Up @@ -438,7 +496,7 @@ public void DuplicateKeysInLogRecordAttributesAndLogScope()
var properties = new ChangeTrackingDictionary<string, string>();
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));
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -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);
}
}
Expand Down
Loading