Performance tracing in ASP.NET middlewares

[madmox]

Problem Statement

// Program.cs

WebApplicationBuilder builder = WebApplication.CreateBuilder(args);
builder.WebHost.UseSentry();

WebApplication app = builder.Build();
app.Use(async (context, next) =>
{
    ISpan s1 = SentrySdk.GetSpan(); // null
    await next();
    ISpan s2 = SentrySdk.GetSpan(); // null
});
app.UseRouting();
app.MapControllers();

app.Run();

Tracing works fine inside my controller and all associated filters, but I would like to trace middleware operations in the same transaction as well, which does not seem possible with the current SDK implementation (SentrySdk.GetSpan() is null in the middleware).

Solution Brainstorm

Maybe it should be (is?) possible to start the transaction earlier in the ASP.NET pipeline?

[jamescrosswell]

Hi @madmox ,

To create traces manually you'll need to start by creating a transaction and set this on the scope (see docs). SentrySdk.GetSpan() will always return null if Scope.Transaction has not been set.

You can see how this is done internally here: https://github.com/getsentry/sentry-dotnet/blob/37eb4a54cee682bec0d63435ce9959a67fb4656e/src/Sentry/Internal/Hub.cs#L538-L545

Arguably, that functionality could be surfaced in the Public API.

[madmox]

@jamescrosswell: I don't want to create a new transaction. I want to use the "request transaction" Sentry automatically creates somewhere in the pipeline when I use builder.WebHost.UseSentry(); to trace operations in my middelware. Those operations (spans) should be included in the same transaction as operations performed in my controller.

More specifically, I have a middleware that creates an ambiant SQL transaction when the request starts, and commits/rolls back when the HTTP request completes (when the response starts). I want to trace the commit/rollback statement in the same transaction as the other SQL statements.

Maybe your suggestion does that, I should look more into it. But from what I can see, if SentrySdk.GetSpan() returns null when I commit my SQL transaction, then your code will open a new "Sentry" transaction, not add a span to the one the SDK created for the request (which is presumably already finished).

[bitsandfoxes]

Hey @madmox,

I want to use the "request transaction" Sentry automatically creates somewhere in the pipeline when I use builder.WebHost.UseSentry(); to trace operations in my middelware.

I gave this a try locally because this is how I expected it to work and now I'm in a "it works on my machine" situation. The SentryTracingMiddleware runs before app.Use so there should definitely be a transaction available for you to add a childspan to. Do you have tracing enabled? I.e. options.TracesSampleRate = 1.0f?

[madmox]

According to the doc, I should be able to retrieve the current transaction by using ISpan span = SentrySdk.GetSpan();. Simple repro sample I came up with:

// Program.cs
using Microsoft.AspNetCore.Builder;
using Microsoft.AspNetCore.Hosting;
using Microsoft.AspNetCore.Http;
using Microsoft.AspNetCore.Mvc;
using Microsoft.Extensions.DependencyInjection;
using Sentry;

WebApplicationBuilder builder = WebApplication.CreateBuilder(args);
builder.WebHost.UseSentry("xxx");
builder.Services.AddControllers();

WebApplication app = builder.Build();
app.Use(async (context, next) =>
{
    ISpan span1 = SentrySdk.GetSpan(); // null
    await next();
    ISpan span2 = SentrySdk.GetSpan(); // null
});
app.UseRouting();
app.MapControllers();

app.Run();

[ApiController]
public class TestController
{
    [HttpGet]
    [Route("")]
    public IActionResult Get()
    {
        ISpan span = SentrySdk.GetSpan(); // not null
        return new StatusCodeResult(StatusCodes.Status204NoContent);
    }
}

<Project Sdk="Microsoft.NET.Sdk.Web">

  <PropertyGroup>
    <TargetFramework>net6.0</TargetFramework>
  </PropertyGroup>

  <ItemGroup>
    <PackageReference Include="Sentry.AspNetCore" Version="4.7.0" />
  </ItemGroup>

</Project>

After investigating, I found out that it works when using .NET 8 (TargetFramework=net8.0 in the .csproj) OR if I use .NET 6 but remove the line app.UseRouting(); (doesn't work if I move this line before my middleware though) 🤔

[bitsandfoxes]

This reminds me of something @jamescrosswell came across a while back! Didn't we make some changes to the initialization and setup to take care of the order internally?

[jamescrosswell]

@madmox sorry I didn't read your original post carefully enough. Sentry's tracing module is registered automatically after the call to app.UseRouting (see https://github.com/getsentry/sentry-dotnet/pull/2602).

So I tweaked the AspNetCoreBasic sample to do this:

                app.Use(async (_, next) =>
                {
                    var s1 = SentrySdk.GetSpan(); // null
                    Console.WriteLine($"Active span before first middleware: {s1?.SpanId ?? "null"}");
                    await next();
                    var s2 = SentrySdk.GetSpan(); // null
                    Console.WriteLine($"Active span after first middleware: {s2?.SpanId ?? "null"}");
                });
                app.UseRouting();
                app.Use(async (_, next) =>
                {
                    var s1 = SentrySdk.GetSpan(); // null
                    Console.WriteLine($"Active span before second middleware: {s1?.SpanId ?? "null"}");
                    await next();
                    var s2 = SentrySdk.GetSpan(); // null
                    Console.WriteLine($"Active span after second middleware: {s2?.SpanId ?? "null"}");
                });

                app.UseEndpoints(endpoints =>
                {
                    // Reported events will be grouped by route pattern
                    endpoints.MapGet("/", context => context.Response.WriteAsync("Hello World!"));
               }

And making a request to the root / route gives the following console output:

info: Microsoft.AspNetCore.Hosting.Diagnostics[1]
      Request starting HTTP/1.1 GET http://localhost:59740/echo - -
info: Sentry.ISentryClient[0]
      Sentry trace header is null. Creating new Sentry Propagation Context.
Active span before first middleware: null
info: Sentry.ISentryClient[0]
      Started transaction with span ID '492d591e96dfcc00' and trace ID '349164adf0f348e0901b66ad6c8a941b'.
Active span before second middleware: 492d591e96dfcc00
Active span after second middleware: 492d591e96dfcc00
info: Sentry.ISentryClient[0]
      Capturing transaction.
info: Sentry.ISentryClient[0]
      Envelope queued up: '9f6734da40144c2b822d5368994f0b3a'
Active span after first middleware: null
info: Microsoft.AspNetCore.Hosting.Diagnostics[2]
      Request finished HTTP/1.1 GET http://localhost:59740/echo - - - 404 0 - 15.5105ms
info: Sentry.ISentryClient[0]
      HttpTransport: Envelope '9f6734da40144c2b822d5368994f0b3a' successfully sent.

If you really want/need to, you could theoretically enable Sentry's tracing before the UseRouting middleware so that it was available earlier in the request pipeline. However things like the names of routes won't work property if you do that and we can't guarantee the behaviour of the auto-instrumentation in this case though. Ideally you can register your own middleware after the call to UseRouting.

[madmox]

Your example doesn't work for me. As I wrote in my previous message:

• With .NET 6, the current span is always null in my middleware if I explicitly call app.UseRouting() and always not null if I let the framework register routing implicitly (by not calling app.UseRouting()). The position of my middleware relative to routing does not matter.
• With .NET 8, the current span is never null, regardless of any explicit or implicit call to app.UseRouting().

using Microsoft.AspNetCore.Builder;
using Microsoft.AspNetCore.Hosting;
using Sentry;
using System;

WebApplicationBuilder builder = WebApplication.CreateBuilder(args);
builder.WebHost.UseSentry("<your DSN here>");

WebApplication app = builder.Build();
app.Use(async (_, next) =>
{
    Console.WriteLine($"Active span before first middleware: {SentrySdk.GetSpan()?.SpanId ?? "null"}");
    await next();
    Console.WriteLine($"Active span after first middleware: {SentrySdk.GetSpan()?.SpanId ?? "null"}");
});
app.UseRouting();
app.Use(async (_, next) =>
{
    Console.WriteLine($"Active span before second middleware: {SentrySdk.GetSpan()?.SpanId ?? "null"}");
    await next();
    Console.WriteLine($"Active span after second middleware: {SentrySdk.GetSpan()?.SpanId ?? "null"}");
});
app.MapGet("/", () => "Hello World!");

app.Run();

With .NET 6:

info: Microsoft.AspNetCore.Hosting.Diagnostics[1]
      Request starting HTTP/1.1 GET https://localhost:5100/ - -
Active span before first middleware: null
Active span before second middleware: null
info: Microsoft.AspNetCore.Routing.EndpointMiddleware[0]
      Executing endpoint 'HTTP: GET /'
info: Microsoft.AspNetCore.Routing.EndpointMiddleware[1]
      Executed endpoint 'HTTP: GET /'
Active span after second middleware: null
Active span after first middleware: null
info: Microsoft.AspNetCore.Hosting.Diagnostics[2]
      Request finished HTTP/1.1 GET https://localhost:5100/ - - - 200 - text/plain;+charset=utf-8 101.6752ms

With .NET 8 (also with .NET 6 when I comment out the line app.UseRouting();):

info: Microsoft.AspNetCore.Hosting.Diagnostics[1]
      Request starting HTTP/1.1 GET https://localhost:5100/ - - -
Active span before first middleware: bd9a3db9ac2df702
Active span before second middleware: bd9a3db9ac2df702
info: Microsoft.AspNetCore.Routing.EndpointMiddleware[0]
      Executing endpoint 'HTTP: GET /'
info: Microsoft.AspNetCore.Routing.EndpointMiddleware[1]
      Executed endpoint 'HTTP: GET /'
Active span after second middleware: bd9a3db9ac2df702
Active span after first middleware: bd9a3db9ac2df702
info: Microsoft.AspNetCore.Hosting.Diagnostics[2]
      Request finished HTTP/1.1 GET https://localhost:5100/ - 200 - text/plain;+charset=utf-8 63.8173ms

[bitsandfoxes]

Thanks @madmox, for being so persistent. I can reproduce this locally with our own samples as well. Looks like a bug to me. This behaviour should not change based on the TFM.

[jamescrosswell]

I can reproduce this locally with our own samples as well.

I can't reproduce this locally, targeting net6.0 on macOS using our AspNetCore.Basic sample... I'm not sure what you guys are doing differently (or conversely, what I'm doing differently).

Could one of you push a repro up to a github repo that I could clone?

[madmox]

Not sure about your AspNetCore.Basic sample, but can you reproduce using these 2 files?

Program.cs:

using Microsoft.AspNetCore.Builder;
using Microsoft.AspNetCore.Hosting;
using Sentry;
using System;

WebApplicationBuilder builder = WebApplication.CreateBuilder(args);
builder.WebHost.UseSentry("https://public@sentry.example.com/1");

WebApplication app = builder.Build();
app.Use(async (_, next) =>
{
    Console.WriteLine($"Active span before first middleware: {SentrySdk.GetSpan()?.SpanId ?? "null"}");
    await next();
    Console.WriteLine($"Active span after first middleware: {SentrySdk.GetSpan()?.SpanId ?? "null"}");
});
app.UseRouting();
app.Use(async (_, next) =>
{
    Console.WriteLine($"Active span before second middleware: {SentrySdk.GetSpan()?.SpanId ?? "null"}");
    await next();
    Console.WriteLine($"Active span after second middleware: {SentrySdk.GetSpan()?.SpanId ?? "null"}");
});
app.MapGet("/", () => "Hello World!");

app.Run();

Application.csproj:

<Project Sdk="Microsoft.NET.Sdk.Web">

  <PropertyGroup>
    <TargetFramework>net6.0</TargetFramework>
  </PropertyGroup>

  <ItemGroup>
    <PackageReference Include="Sentry.AspNetCore" Version="4.7.0" />
  </ItemGroup>

</Project>

Copy both files in a new directory (no change needed), cd into it, and execute dotnet run, and access your kestrel server using your web browser (usually at http://localhost:5000/).

Then kill the server, change the target framework to net8.0, execute again, and refresh your browser.