newrelic / newrelic-dotnet-agent

The New Relic .NET language agent.
Apache License 2.0
97 stars 62 forks source link

Context data capture does not work with Microsoft.Extensions.Logging and the built-in Console log output #2261

Closed nr-ahemsath closed 7 months ago

nr-ahemsath commented 8 months ago

See this issue for more context: https://github.com/newrelic/newrelic-dotnet-agent/issues/2251

There is currently the following comments and code in the wrapper for Microsoft.Extensions.Logging that does context data capture:

// MEL keeps an array of scope handlers. We can ask one of them for the current scope data.

// Get the array of ScopeLoggers (logger.ScopeLoggers[])
var getLoggersArrayFunc = _getLoggersArray ??= VisibilityBypasser.Instance.GeneratePropertyAccessor<dynamic>(logger.GetType(), "ScopeLoggers");
var loggers = getLoggersArrayFunc(logger);

// Get the first ScopeLogger in the array (logger.ScopeLoggers[0])
// If there is more than one scope logger, they've all received the same data, so the first
// one should be fine
 object firstLogger = loggers.GetValue(0);

However, the statement "if there is more than one scope logger, they've all the received the same data" does not appear to be true in at least one scenario. The linked feature request describes the scenario of having an ASP.NET Core webapi application configured to use MEL's built-in Console logger with the "IncludeScopes" option set to true. Debugging through the agent in this scenario, I found that there were three ScopeLoggers in the array, and only the last one had the ExternalScopeProvider property set to something other than null.

I'm not really sure what the difference is between the scenario the customer described and how our integration tests for context data capture with MEL differ (other than that the integration tests use a simple console app, not an ASP.NET Core web app, which might have other logging configuration baked in going on).

workato-integration[bot] commented 8 months ago

https://new-relic.atlassian.net/browse/NR-231906

lowell-trimble commented 7 months ago

Yes, this is a bug I've also encountered. It's actually the last ScopeLogger which has the ExternalScopeProvider set.

To avoid this bug, you have to remove all other logging providers so that the Console logging provider is the one and only provider, making it both the first and last.

This can be seen here in Microsoft's repo, that the ExternalScopeProvider is only set on the last ScopeLogger, the rest are null. https://github.com/dotnet/runtime/blob/main/src/libraries/Microsoft.Extensions.Logging/src/LoggerFactory.cs#L250