Framework breadcrumbs are not captured in the event

[madmox]

Environment

Using ASP.NET Core 3.1 and Sentry.AspNetCore 3.12.3, sending events to our Sentry SaaS account.

Steps to Reproduce

Send an event to Sentry after having performed an HTTP request with a System.Net.Http.HttpClient, with global default log level of Information and Sentry breadcrumbs enabled at the Information level.

Expected Result

All information logs are included in the event, including the request / response information logs from System.Net.Http.HttpClient (request method / URL, response code).

Actual Result

System.* / Microsoft.* logs appear to be excluded from breadcrumbs. Other information logs are correctly included (application and third party libraries). System.* / Microsoft.* logs are correctly displayed in the console when running locally with the same appsettings.json.

Is this normal behavior (e.g. to avoid overloading the breacrumbs array)? Some of these logs are pretty useful to perform diagnostics.

[madmox]

Sample reproduction code using a .NET 6 Console app and latest (3.14.1) Sentry.Extensions.Logging package :

Program.cs

using Microsoft.Extensions.Configuration;
using Microsoft.Extensions.DependencyInjection;
using Microsoft.Extensions.Logging;
using System.IO;
using System.Net.Http;

IConfigurationRoot config = new ConfigurationBuilder()
    .SetBasePath(Directory.GetCurrentDirectory())
    .AddJsonFile("appsettings.json", optional: false)
    .Build();
var services = new ServiceCollection();
services.AddLogging(logging =>
{
    logging.AddConfiguration(config.GetSection("Logging"));
    logging.AddConsole();
    logging.AddSentry();
});
services.AddHttpClient();
ServiceProvider serviceProvider = services.BuildServiceProvider();

var logger = (ILogger)serviceProvider.GetRequiredService<ILogger<Program>>();
IHttpClientFactory httpClientFactory = serviceProvider.GetRequiredService<IHttpClientFactory>();
HttpClient http = httpClientFactory.CreateClient();

logger.LogInformation("Before HTTP request."); // included as breadcrumb
string result = await http.GetStringAsync("https://www.google.com/"); // info logs not included as breadcrumbs
logger.LogInformation("Response length is {length}.", result.Length); // included as breadcrumb
logger.LogError("FAKE ERROR");

appsettings.json

{
  "Logging": {
    "LogLevel": {
      "Default": "Information"
    },
    "Sentry": {
      "Dsn": "<!!changeme!!>",
      "MinimumBreadcrumbLevel": "Information",
      "MinimumEventLevel": "Warning"
    }
  }
}

csproj

<Project Sdk="Microsoft.NET.Sdk">
  <PropertyGroup>
    <OutputType>Exe</OutputType>
    <TargetFramework>net6.0</TargetFramework>
  </PropertyGroup>
  <ItemGroup>
    <Content Include="appsettings.json" CopyToOutputDirectory="PreserveNewest" />
    <PackageReference Include="Microsoft.Extensions.Configuration.Json" Version="6.0.0" />
    <PackageReference Include="Microsoft.Extensions.Logging.Console" Version="6.0.0" />
    <PackageReference Include="Sentry.Extensions.Logging" Version="3.14.1" />
  </ItemGroup>
</Project>

[lucas-zimerman]

It seems like it's not getting initialized in time (not reading the data from appsettings?)

You can check that by checking SentrySdk.IsEnabled before executing await http.GetStringAsync("https://www.google.com/"); you'll notice that it says false so the sdk at that moment is disabled.

If you try to set the dsn inside of AddSentry logging.AddSentry(options => { options.Dsn = "https://[email protected]/5428537"; }); At the same line it'll say the SDK is not enabled. Although it didn't register the request breadcrumb on my side and requires further investigation.

[madmox]

I have no problem with the SDK initialization on my side. The error event is captured, and if I add a logger.LogInformation() call before the HTTP request then this application breadcrumb is included in the event, although the System.* logs from HttpClient still aren't (I updated the sample code to reflect the point).

[mattjohnsonpint]

I did some debugging. The issue is that the breadcrumbs are stored with the current logging scope, and are lost after that scope is disposed. Methods like HttpClient.GetStringAsync create their own logging scope, which is disposed after the method completes (not when the HttpClient itself is disposed).

The output from the sample console program shows the logging scopes (as numbers in the square brackets):

info: Program[0]
      Before HTTP request.
info: System.Net.Http.HttpClient.Default.LogicalHandler[100]
      Start processing HTTP request GET https://www.google.com/
info: System.Net.Http.HttpClient.Default.ClientHandler[100]
      Sending HTTP request GET https://www.google.com/
info: System.Net.Http.HttpClient.Default.ClientHandler[101]
      Received HTTP response headers after 362.3386ms - 200
info: System.Net.Http.HttpClient.Default.LogicalHandler[101]
      End processing HTTP request after 380.7454ms - 200
info: Program[0]
      Response length is 53415.
fail: Program[0]
      FAKE ERROR

By the time the error is thrown in scope 0, scope 101 (where the breadcrumbs were added) has already been disposed.

The SentryLogger appears to be handling logging scopes correctly. The questions is, do we want breadcrumbs from child scopes to pass up to their parent scopes when they are disposed? Or do we want to discard those breadcrumbs like we currently do?

[madmox]

Interesting. I could reproduce the behavior without involving HTTP calls by using logging scopes, so I can confirm that the issue is probably not related to System.* / Microsoft.* logs being filtered out as I suspected.

using Microsoft.Extensions.Configuration;
using Microsoft.Extensions.DependencyInjection;
using Microsoft.Extensions.Logging;
using System;
using System.IO;

IConfigurationRoot config = new ConfigurationBuilder()
    .SetBasePath(Directory.GetCurrentDirectory())
    .AddJsonFile("appsettings.json", optional: false)
    .Build();
var services = new ServiceCollection();
services.AddLogging(logging =>
{
    logging.AddConfiguration(config.GetSection("Logging"));
    logging.AddConsole();
    logging.AddSentry();
});
ServiceProvider serviceProvider = services.BuildServiceProvider();

var logger = (ILogger)serviceProvider.GetRequiredService<ILogger<Program>>();
logger.LogInformation("SCOPE 0"); // included as breadcrumb in the event
using (IDisposable scope1 = logger.BeginScope("Scope 1"))
{
    using (IDisposable scope2 = logger.BeginScope("Scope 2"))
    {
        logger.LogInformation("SCOPE 2"); // NOT included as breadcrumb in the event
    }
    logger.LogInformation("SCOPE 1"); // included as breadcrumb in the event
    logger.LogError("FAKE ERROR");
}

Though I'm not sure why you would want to discard logs generated in child scopes from the breadcrumbs?

[mattjohnsonpint]

This won't be a simple fix, as it would require some changes that would significantly change the current behavior. As documented here (emphasis mine):

The scope will hold useful information that should be sent along with the event. For instance contexts or breadcrumbs are stored on the scope. When a scope is pushed, it inherits all data from the parent scope and when it pops all modifications are reverted.

The default SDK integrations will push and pop scopes intelligently. For instance web framework integrations will create and destroy scopes around your routes or controllers.

So, right now everything is working as designed. The problem is that it's not always obvious that calling a bit of code (like methods on HttpClient) will create and dispose a new logging scope. As a developer, I don't have a clean way to explicitly opt-in to keep items from child scopes.

FWIW, I tried the following three different approaches for resolving this.

• Attempt 1 copies breadcrumbs from the child scope to the parent scope.
• Attempt 2 uses the existing lock/unlock scope APIs. The net result is that _hub.PushScope doesn't actually push a new scope but instead applies the state to the current scope. In talking with @bruno-garcia, I've come to understand that the whole lock/unlock thing is somewhat of a hack anyway and should probably be removed at some point.
• Attempt 3 completely avoids _hub.PushScope and just makes logger.BeginScope a no-op - effectively just using a single Sentry scope. In doing so, there are three unit tests that break because they were testing the old behavior.

IMHO, none of these is the right approach. Making this breaking change would likely have other unintended side effects, such as long trails of breadcrumbs and other events that should have been discarded.

We need to think through this better, but probably not right at this moment. Will keep it on the backlog for now. Thanks.

[mattjohnsonpint]

Note also that this issue doesn't occur if you enable Global Mode.

You can turn it on with this:

logging.AddSentry(options =>
    {
        options.IsGlobalModeEnabled = true;
    })

or in appsettings.json:

{
    "Logging": {
        "Sentry": {
            "IsGlobalModeEnabled": true
        }
    }
}

(Though global mode doesn't makes sense for web apps.)

[mattjohnsonpint]

We're considering adding a boolean option to opt-out of binding the logging scope to the Sentry scope. That would prevent a breaking change (off by default), but give the option to include this extra information.

[madmox]

Making this breaking change would likely have other unintended side effects, such as long trails of breadcrumbs and other events that should have been discarded.

This remark of yours is important in my opinion. If these use cases exist, wouldn't there be applications where you want both behaviors? i.e. drop undesired events unrelated to the error (I still have to find a use case), and include others (like the HTTP client logs in my client example). It's the whole "dropping child logging scopes" that I don't understand and that should be questioned in the first place - I think.

If the behavior has no use case, the boolean parameter approach is good, but it should be set to true by default starting with the next major release and marked as obsolete from there. If this behavior has use cases, I think you might want to consider another approach that allows users more control than a simple on/off switch.

Or maybe the "fix" should be made in .NET and they should stop using nested logging scopes in wrong places, but I doubt that's the case (I think the primary use case for logging scopes is adding hierarchical metadata to a set of related logs, which could make sense here).