Performance Monitoring using Sentry, Serilog, and AspNetCore

[mpainenz]

Is it possible to get the Sentry Tracing to work, when using the Sentry Serilog ASP Core integration Library?

Sorry to log this as a bug, it's more of a configuration question.

Environment

On-premise - Sentry 21.7.0.dev0

.NET 5.0 Sentry.AspNetCode v3.8.2 Sentry.Serilog v3.8.2

Steps to Reproduce

Using the following in our appsettings.json file to enable TracesSampleRate:

 "Serilog": {
    "Using": [ "Serilog.Sinks.Console", "Sentry.Serilog" ],
    "MinimumLevel": "Debug",
    "WriteTo": [
      {
        "Name": "Console"
      },
      {
        "Name": "Sentry",
        "Args": {
          "MinimumBreadcrumbLevel": "Debug",
          "MaxBreadcrumbs": 500,
          "MinimumEventLevel": "Warning",
          "DSN": "http://73e3c7c0d70947c5b764751db123f89d@ourlocalonpremisesentry.lan:9000/3",
          "AttachStacktrace": true,
          "SendDefaultPii": true,
          "IncludeActivityData": true,
          "IncludeRequestPayload": true,
          "TracesSampleRate": 1.0,
          "Release":  "Development 20210721"
        }
      },

    ],
    "Enrich": [ "FromLogContext", "WithMachineName", "WithExceptionDetails", "WithProcessId", "WithThreadId" ]
  }

Running the following function does not seem to populate any Trace Data to make it's way into the "Performance" section of Sentry.

public async Task<Customer> GetCustomer(string customerid, bool getservicesummary = false, bool usecached = false)
        {
            var transaction = SentrySdk.StartTransaction("get-customer-transaction", "get-customer-operation");
            var span = transaction.StartChild("test-child-operation");

            Customer c = null;
            if (usecached && (_cache.TryGetValue("customer-" + customerid, out c)))
            {
                return c;
            }

            await _conn.OpenAsync();
            try
            {
               // Program Logic ommitted
            finally
            {
                await _conn.CloseAsync();
            }
            if (usecached) _cache.Set("customer-" + customerid, c, DateTime.Now.AddMinutes(1));

            span.Finish();
            transaction.Finish();
            return c;
        }

Other relevant Code:

                .UseWindowsService()
                .ConfigureWebHostDefaults(webBuilder => {
                    webBuilder.UseStartup<Startup>()
                    //.UseSentry() //UseSentry is not in use here, as we use the Serilog Integration
                    .UseSerilog();
                });

The following is also not in use, as we rely on the Serilog integration, not the standard Sentry one. //app.UseSentryTracing();

Expected Result

The Performance section of Sentry would show something new

Actual Result

I still see the Pinpoint problems image when navigating to the "Performance" section of Sentry

[kanadaj]

I believe if you want to properly initialise the Sentry SDK via only using the Serilog config, you must set InitializeSdk to true. On top of that, if you don't use app.UseSentryTracing(); you will not get any automatic traces from MVC/Razor endpoints, but if you don't need that it should be fine if you set InitializeSdk.

If you don't do this, SentrySdk never gets initialized and by default it returns a Noop instance, as an error reporting pipeline should not ever throw errors itself.

[bruno-garcia]

"DSN": "http://73e3c7c0d70947c5b764751db123f89d@ourlocalonpremisesentry.lan:9000/3",

Does ASP.NET Core/Serilog support binding properties with unmatching casing? The object property is Dsn, I believe you need to fix the casing here

[bruno-garcia]

Also could you please set "Debug": true so we can see in the logs what the SDK is doing?

In the sample you can see the DSN and the debug flags being set:

https://github.com/getsentry/sentry-dotnet/blob/a0b454b94381037708ba5107f1032d9bb1c37bea/samples/Sentry.Samples.AspNetCore.Serilog/appsettings.json#L6-L17

Another example is NuGet Trends where we use both Sentry.AspNetCore and Sentry.Serilog:

https://github.com/dotnet/nuget-trends/blob/663727e8350d35f7e647116acd2144e47069dafc/src/NuGetTrends.Web/appsettings.Production.json#L2-L35

There we rely on ASP.NET Core to init the SDK though not Serilog so the DSN is being passed to the first

[mpainenz]

I believe if you want to properly initialise the Sentry SDK via only using the Serilog config, you must set InitializeSdk to true. On top of that, if you don't use app.UseSentryTracing(); you will not get any automatic traces from MVC/Razor endpoints, but if you don't need that it should be fine if you set InitializeSdk.

If you don't do this, SentrySdk never gets initialized and by default it returns a Noop instance, as an error reporting pipeline should not ever throw errors itself.

Using a combintation of InitializeSdk, and UseSentryTracing() without also calling UseSentry() results in the following exception during startup:

"Unable to resolve service for type 'System.Func`1[Sentry.IHub]' while attempting to activate 'Sentry.AspNetCore.SentryTracingMiddleware'.'"

[mpainenz]

Also could you please set "Debug": true so we can see in the logs what the SDK is doing?

Environment is Development
Loading Development Serilog AppSettings Config From: (Path Omitted)\appsettings.Development.json
  Debug: Logging enabled with ConsoleDiagnosticLogger and min level: Debug
  Debug: Initializing Hub for Dsn: 'http://73e3c7c0d70947c5b764751db123f89d@URLOmitted:9000/3'.
  Debug: Using 'GzipBufferedRequestBodyHandler' body compression strategy with level Optimal.
  Debug: New scope pushed.
  Debug: Registering integration: 'AutoSessionTrackingIntegration'.
  Debug: Registering integration: 'AppDomainUnhandledExceptionIntegration'.
  Debug: Registering integration: 'AppDomainProcessExitIntegration'.
  Debug: Registering integration: 'TaskUnobservedTaskExceptionIntegration'.
[09:48:24 INF] Startup: Configuring Services
  Debug: Configuring the scope.
[09:48:24 INF] Startup: Loading App Settings
  Debug: Configuring the scope.
[09:48:24 INF] Reading Connection String (If this fails, check that application is being run from base directory context)
  Debug: Configuring the scope.
[09:48:24 INF] Connection String: Server=OMITTED
  Debug: Configuring the scope.
[09:48:25 INF] Startup: Configuring Services
  Debug: Configuring the scope.
[09:48:25 INF] Startup: Registering Services
  Debug: Configuring the scope.
[09:48:25 INF] Startup: Configuring JWT
  Debug: Configuring the scope.
[09:48:25 INF] Startup: Configuring Development Controller Authentication
  Debug: Configuring the scope.
[09:48:25 INF] Startup: Registering Swagger
  Debug: Configuring the scope.
[09:48:25 INF] Startup: Configuring Authentication Policies
  Debug: Configuring the scope.
[09:48:25 INF] Startup: Adding Memory Cache
  Debug: Configuring the scope.
[09:48:25 INF] Startup: Loading AWS Configuration
  Debug: Configuring the scope.
  Debug: Configuring the scope.
[09:48:25 FTL] Application startup exception
System.InvalidOperationException: Unable to resolve service for type 'System.Func`1[Sentry.IHub]' while attempting to activate 'Sentry.AspNetCore.SentryTracingMiddleware'.
   at Microsoft.Extensions.Internal.ActivatorUtilities.ConstructorMatcher.CreateInstance(IServiceProvider provider)
   at Microsoft.Extensions.Internal.ActivatorUtilities.CreateInstance(IServiceProvider provider, Type instanceType, Object[] parameters)
   at Microsoft.AspNetCore.Builder.UseMiddlewareExtensions.<>c__DisplayClass5_0.<UseMiddleware>b__0(RequestDelegate next)
   at Microsoft.AspNetCore.Builder.ApplicationBuilder.Build()
   at Microsoft.AspNetCore.Hosting.GenericWebHostService.StartAsync(CancellationToken cancellationToken)
  Debug: Failed to report an error on a session because there is none active.
   Info: Capturing event.
  Debug: Running processor on exception: Unable to resolve service for type 'System.Func`1[Sentry.IHub]' while attempting to activate 'Sentry.AspNetCore.SentryTracingMiddleware'.
  Debug: Creating SentryStackTrace. isCurrentStackTrace: False.
  Debug: Running main event processor on: Event 2fb466b8bdfa42ada827042683bc2bf8
  Debug: Envelope queued up.
  Debug: Configuring the scope.
  Debug: Failed to report an error on a session because there is none active.
   Info: Capturing event.
  Debug: Running processor on exception: Unable to resolve service for type 'System.Func`1[Sentry.IHub]' while attempting to activate 'Sentry.AspNetCore.SentryTracingMiddleware'.
  Debug: Creating SentryStackTrace. isCurrentStackTrace: False.
  Debug: Duplicate Exception detected. Event 023901da7caa45cfb56f0221f403785e will be discarded.
   Info: Event dropped by processor DuplicateEventDetectionEventProcessor
   Info: Disposing the Hub.
  Debug: Disposing SentryClient.
  Debug: Disposing BackgroundWorker.
  Debug: Envelope 2fb466b8bdfa42ada827042683bc2bf8 handed off to transport. #1 in queue.
  Debug: Envelope 2fb466b8bdfa42ada827042683bc2bf8 successfully received by Sentry.
  Debug: Shutdown scheduled. Stopping by: 00:00:02. #0 in queue.
   Info: Exiting the worker with an empty queue.
  Debug: Disposing scope.
  Debug: Disposing SentryScopeManager.

[mpainenz]

It seems that if I just include an empty configuration block for Sentry:

"Sentry": { "Dsn": "", // Set via serilog },

The problem still occurs, and the Serilog config appears to become broken again. I need to essentially replicate all the config within the Sentry block, for it to work for some reason.

[bruno-garcia]

Ultimately the only way to initialize sentry is through: SentrySdk.Init.

The Serilog and ASP.NET Core integrations both have a way to initialize Sentry that are more idiomatic for those libraries/frameworks. Even though not officially supported in any Sentry SDK, the .NET SDK supports being reinitialized. So calling Init a second time will gracefully close the current Hub, flushing any queued events, and will create a new one (with the new options) and will bind that to the SentrySdk static class (so that any integration can find it).

That said, even though not ideal, it's possible to use Serilog first, passing all Sentry options to it, and even in the event that ASP.NET Core fails to start, Sentry will capture that error. And if ASP.NET Core does start properly, the Sentry SDK would be reinitialized by the UseSentry call (assuming all options were also provided to the ASP.NET Core integration). This means the new options (the ones passed to UseSentry or given to appsettings.json's Sentry root property would take effect.

Even with the reinitialization, Serilog would continue to work normally as it was designed to adapt to the SDK being reinitialized and would simply emit context data such as breadcrumbs to the newly initialized Hub within the SentrySdk class.

Finally, I agree with you that's not convenient to have to provide the options twice, and the SDK could be refactored so that ASP.NET Core integration would also have such InitializeSdk property and would simply rely on a previously initialized SDK if it was there instead of reinitializing it with its own options. But that's not the state the SDK is on today. We'd love a PR to improve this flow though but until then the only approach (if you want to make sure errors are captured before ASP.NET Core starts up) is to init it twice (via Serilog and ASP.NET Core).

On NuGet Trends for example I chose to only pass options to the ASP.NET Core integration. Serilog only takes options for the min log levels (what to add as crumb and what to send as event). Things work well but I do have a blind spot there for if the whole process fails to start up. But in my usage it means the container also fails to start so it's pretty obvious.

[mpainenz]

Thanks for taking the time to explain the issue, and that now makes sense in regards to the competing calls to SentrySdk.Init. That explains to me, why including a call to UseSentry() without re-supplying the sentry specific configuration block, will wipe out any sentry configuration supplied by Serilog.

Ultimately, I hope that by raising this issue here, it will assist anyone else who runs into the same issue. I would hope, that the code sample in the repository for the Serilog integration, could be modified, or a new code sample supplied, which demonstrates the recommended approach when wanting to use Serilog and the Tracing features.

Would perhaps it be possible, for the sentry tracing to be a configuration element? I'm guessing that's not straight forward, otherwise it would have been done that way. I suppose that is the main issue, in that the Tracing cannot be set via the Serilog Config.

Hope that makes sense, cheers.

[bruno-garcia]

Thank you for raising and clarifying the steps and outcomes of the different combinations. It's definitely going to be useful to anyone trying to init Serilog+ASP.NET Core and tracing.

I think we can improve docs and also improve the integration. As you said, have the ASP.NET Core integration, in particular tracing (if not the whole thing) be enabled when Sentry was already initialzied in the process. For example, through Serilog's integration.

[bruno-garcia]

We discussed and agree that ASP.NET Core + Serilog is the most common setup out there so adding an explicit clarification about how to configure these two together is pretty important. The clarification on the doc can live under the Serilog docs and the aspnetcore page just have a note and a link

[patrickklaeren]

For anyone who comes here, after much trial and error and just observing what happens in a test application, my configuration (slimmed down) is as follows:

builder.WebHost.UseSentry(d =>
{
    d.Dsn = // DSN;
    // And other configuration
});

Log.Logger = new LoggerConfiguration()
    .WriteTo.Sentry()
    .CreateLogger();

builder.Host.UseSerilog();

var app = builder.Build();
app.UseSerilogRequestLogging();
app.UseRouting();
app.UseSentryTracing();

This does everything you'd expect it to do in terms of logging on Sentry's side as far as I can tell (without duplicates).

Usually I am very happy with what Sentry offers for developers - but the Serilog integration definitely does not make this straight forward or obvious.

Happy to be corrected if the above is incorrect.

[kanadaj]

@patrickklaeren It doesn't help that Serilog itself has 2 different ways to implement:

• Serilog.Extensions.Hosting
• Serilog.Extensions.Logging

If you use the former, Serilog replaces the system ILoggerFactory with its own implementation, short circuiting all ILogger implementations. See: https://github.com/serilog/serilog-extensions-hosting/blob/main/src/Serilog.Extensions.Hosting/SerilogHostBuilderExtensions.cs#L68

If you use the latter, Serilog is registered as a provider inside the Microsoft.Extensions.Logging pipeline, so other MEL loggers remain functional. If you then register Sentry using the default WebHost call, it'd register a listener for MEL, and then you also register a listener to Serilog, ending up with 2 different log writers that write to Serilog. See: https://github.com/serilog/serilog-extensions-logging/blob/dev/src/Serilog.Extensions.Logging/SerilogLoggingBuilderExtensions.cs#L35

I've actually raised this with @mattjohnsonpint on Discord just about a month ago since this results in some inconsistent behaviour, but the root cause isn't caused by Sentry but by Serilog's own inconsistent implementation.

[mattjohnsonpint]

@patrickklaeren - Thanks for the feedback, and sorry for any confusion. We can work to improve the documentation, but ideally it would be great if we could design a better API for a future major version that would lead folks down the path of success.

As @kanadaj mentioned, there are some challenges due to Serilog's internal behaviors. We also need to have both a clean path for Serilog with ASP.NET Core (and others that use ILogger + ILoggingBuilder), as well as Serilog in plain console applications that don't use DI or logging extensions.

I'm open considering potential breaking changes to our design, if anyone has ideas here.

Thanks.

[bitsandfoxes]

Considering this closed as part of https://github.com/getsentry/sentry-dotnet/pull/2928