sentry-dotnet
sentry-dotnet copied to clipboard
getsentry
Suspicious warning messages with tracing enabled (Trying to close a span that was already garbage collected)
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
- Configure aspnet project to use Sentry tracing (
app.UseSentryTracing()) - Create controller that creates EF DB context and queries something from DB
- 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.
Thanks for raising @ZlobnyiSerg Those spans should have been closed before so something we need to look at.
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
We need to replace the logic that holds the spans references from here
https://github.com/getsentry/sentry-dotnet/blob/12c46e1b8a56211075cab11a9b32acc932ef7f35/src/Sentry.DiagnosticSource/Internals/DiagnosticSource/SentryEFCoreListener.cs#L43-L45 One approach that could be followed is to do something similar to what was done on SqlListener https://github.com/getsentry/sentry-dotnet/blob/12c46e1b8a56211075cab11a9b32acc932ef7f35/src/Sentry.DiagnosticSource/Internals/DiagnosticSource/SentrySqlListener.cs#L92
https://github.com/getsentry/sentry-dotnet/blob/12c46e1b8a56211075cab11a9b32acc932ef7f35/src/Sentry.DiagnosticSource/Internals/DiagnosticSource/SentrySqlListener.cs#L176-L177
Where we store the spans directly into the Scope transaction and locate them by the OperationId given by KeyValuePair<string, object?> value.
@lucas-zimerman - Any update on this one?
The warning noise was reduced on #1368.
As pointed on this comment https://github.com/getsentry/sentry-dotnet/issues/1350#issuecomment-996915765 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
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.
