Suspicious warning messages with tracing enabled (Trying to close a span that was already garbage collected)

[ZlobnyiSerg]

Environment

<PackageReference Include="Sentry" Version="3.11.1" />
<PackageReference Include="Sentry.AspNetCore" Version="3.11.1" />
<PackageReference Include="Sentry.Extensions.Logging" Version="3.11.1" />
.net 6

Steps to Reproduce

1. Configure aspnet project to use Sentry tracing (app.UseSentryTracing())
2. Create controller that creates EF DB context and queries something from DB
3. Call this controller

Expected Result

No warnings in log file from Sentry

Actual Result

Lot of warning messages coming from Sentry:

[11:40:07 WRN] Trying to close a span that was already garbage collected. Connection
[11:40:07 WRN] Trying to close a span that was already garbage collected. QueryExecution
[11:40:07 WRN] Trying to close a span that was already garbage collected. QueryCompiler

I'm not sure if this is critical for functioning, but this makes noise in logs (with default configuration). I had to raise level for Sentry to Error.
If this is intended behaviour, please close this issue.

[bruno-garcia]

Thanks for raising @ZlobnyiSerg
Those spans should have been closed before so something we need to look at.

[lucas-zimerman]

#1368 will resolve this problem.

[bruno-garcia]

Should be fixed on 3.12.1.
Please reopen otherwise.

[ZlobnyiSerg]

I've updated to 3.12.1, now we have less warnings but they're still there. For example:

[19:52:55 INF] Route matched with {action = "Update", controller = "Customers", page = ""}. Executing controller action with signature System.Threading.Tasks.Task`1[Microsoft.AspNetCore.Mvc.IActionResult] Update(Int32, Model, System.Threading.CancellationToken) on controller Checkpoint.Web.Api.Controllers.CustomersController (Checkpoint.Web.Api).
[19:52:55 WRN] Trying to close a span that was already garbage collected. Connection
[19:52:55 INF] Envelope '65dc851d09894611b90e90e9d2abef20' successfully received by Sentry.
[19:52:56 WRN] Trying to close a span that was already garbage collected. Connection
[19:52:56 WRN] Trying to close a span that was already garbage collected. Connection
[19:52:56 WRN] Trying to close a span that was already garbage collected. Connection
[19:52:56 WRN] Trying to close a span that was already garbage collected. Connection
[19:52:56 WRN] Trying to close a span that was already garbage collected. Connection
[19:52:56 WRN] Trying to close a span that was already garbage collected. Connection
[19:52:56 WRN] Trying to close a span that was already garbage collected. Connection

[ZlobnyiSerg]

@bruno-garcia I can't reopen this issue, maybe I have no rights?

[lucas-zimerman]

We need to replace the logic that holds the spans references from here

sentry-dotnet/src/Sentry.DiagnosticSource/Internals/DiagnosticSource/SentryEFCoreListener.cs

Lines 43 to 45 in 12c46e1

	private AsyncLocal<WeakReference<ISpan>> _spansCompilerLocal = new();
	private AsyncLocal<WeakReference<ISpan>> _spansQueryLocal = new();
	private AsyncLocal<WeakReference<ISpan>> _spansConnectionLocal = new();

One approach that could be followed is to do something similar to what was done on SqlListener

sentry-dotnet/src/Sentry.DiagnosticSource/Internals/DiagnosticSource/SentrySqlListener.cs

Line 92 in 12c46e1

transaction?.StartChild(operation) is { } connectionSpan)

sentry-dotnet/src/Sentry.DiagnosticSource/Internals/DiagnosticSource/SentrySqlListener.cs

Lines 176 to 177 in 12c46e1

	private static ISpan? TryGetQuerySpan(Scope scope, Guid operationId)
	=> scope.Transaction?.Spans.FirstOrDefault(span => TryGetOperationId(span) == operationId);

Where we store the spans directly into the Scope transaction and locate them by the OperationId given by KeyValuePair<string, object?> value.

[mattjohnsonpint]

@lucas-zimerman - Any update on this one?

[lucas-zimerman]

@lucas-zimerman - Any update on this one?

The warning noise was reduced on #1368.

As pointed on this comment #1350 (comment) the current code doesn't work correctly with multiple connections/queries on the same transaction, Ideally we could follow what was implemented on SentrySqlListener where the spans are located inside of the current active Transaction instead of an AsyncLocal WeakReference. But so far this change in the code wasn't developed

[WatchDogsDev]

When this noise will be cancelled ?

[jamescrosswell]

I'm pretty sure all of the above will be addressed in Fix/DB Connection spans presented poorly #2409. The Trying to close a span that was already garbage collected error was being surfaced because Sentry couldn't find the original spans that needed to be finished. Per the comment above we're no longer using AsyncLocal<WeakReference<ISpan>> to store a reference to the original spans and instead storing the correlation id that is supplied by diagnostics in the spans themselves.

I'll leave this issue open until the fix above is made available in the next release.

[jamescrosswell]

Closing this issues as it should be fixed with the 3.33.1 release.