Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Fix warning caused by db connection span closed prematurely #2068

Merged
merged 10 commits into from
Dec 2, 2022

Conversation

mattjohnsonpint
Copy link
Contributor

In #1179, some logic was added to close connection spans when WriteTransactionCommitAfter. The comments from the state that WriteConnectionCloseAfter was not called in certain cases. However, after investigating, I believe this was an incorrect assumption. The actual reason WriteConnectionCloseAfter may not fire is when the connection is actually held open. Committing a transaction isn't a good place to close the connection span, because more than one command (and more than one transaction) can execute on a given connection.

Indeed, our own RecordsEf integration test (added later) was showing the connection span warning, because both the WriteTransactionCommitAfter and WriteConnectionCloseAfter events were firing. Since the first one closed the connection span, the second one failed to find an unfinished span.

Therefore, the fix is to remove that logic and close the connection span only with WriteConnectionCloseAfter.

Also, some of our integration tests were not capturing the connection span correctly in the first place - because they were re-using a connection that was opened automatically by creating the LocalDB instance, which was done before the hub was initialized. I fixed these tests such that they open, use, and close a new db connection within the Sentry transaction being captured.

As a sanity check, I ran the new tests with the versions of EF Core and SQL Client that were used at the time #1179 was authored, and I was not able to get any scenario where WriteConnectionCloseAfter was not called. Thus, it wasn't related to some other older EF/SQL bug.

Also, a nice side-effect of this change is that connection statistics are now captured in more cases.

I'll drop some more comments inline.

Should fix #2060 (at least in part)

@mattjohnsonpint
Copy link
Contributor Author

FYI, here's the log output of RecordsEf before applying this fix. You can see the warning

[Debug 00:00:00.36]: Initializing Hub for Dsn: 'https://d4d82fc1c2c4032a83f3a29aa3a3aff@fake-sentry.io:65535/2147483647'.
[Debug 00:00:00.36]: Starting BackgroundWorker.
[Debug 00:00:00.36]: BackgroundWorker Started.
[Debug 00:00:00.37]: New scope pushed.
[Debug 00:00:00.37]: Registering integration: 'AutoSessionTrackingIntegration'.
[Debug 00:00:00.37]: Registering integration: 'AppDomainUnhandledExceptionIntegration'.
[Debug 00:00:00.37]: Registering integration: 'AppDomainProcessExitIntegration'.
[Debug 00:00:00.37]: Registering integration: 'UnobservedTaskExceptionIntegration'.
[Debug 00:00:00.37]: Registering integration: 'SentryDiagnosticListenerIntegration'.
[Debug 00:00:00.37]: Registering SQL Client integration.
[Debug 00:00:00.38]: Failed to report an error on a session because there is none active.
[Info 00:00:00.38]: Capturing event.
[Debug 00:00:00.38]: Running processor on exception: my exception
[Debug 00:00:00.38]: Creating SentryStackTrace. isCurrentStackTrace: False.
[Debug 00:00:00.39]: Running main event processor on: Event 656421b7b3864babb2a1d90638f253d3
[Debug 00:00:00.39]: Enqueuing envelope 656421b7b3864babb2a1d90638f253d3
[Info 00:00:00.39]: Envelope queued up: '656421b7b3864babb2a1d90638f253d3'
[Debug 00:00:00.39]: Envelope handed off to transport (event ID: '656421b7b3864babb2a1d90638f253d3'). 1 items in queue.
[Debug 00:00:00.39]: De-queueing event 656421b7b3864babb2a1d90638f253d3
[Debug 00:00:00.47]: Registering EF Core integration
[Warning 00:00:00.98]: Trying to get a span of type Connection with operation id 8ef22b15-78cc-48fd-b6e2-e85071dfeb7e, but it was not found.
[Debug 00:00:01.15]: Enqueuing envelope 7b530cc7faba4bf3ad93da77ca86ca1c
[Info 00:00:01.15]: Envelope queued up: '7b530cc7faba4bf3ad93da77ca86ca1c'
[Info 00:00:01.15]: Disposing the Hub.
[Debug 00:00:01.15]: Envelope handed off to transport (event ID: '7b530cc7faba4bf3ad93da77ca86ca1c'). 1 items in queue.
[Debug 00:00:01.15]: De-queueing event 7b530cc7faba4bf3ad93da77ca86ca1c
[Debug 00:00:01.15]: Successfully flushed all events up to call to FlushAsync.

After the changes, the warning is gone.

[Debug 00:00:00.24]: Initializing Hub for Dsn: 'https://d4d82fc1c2c4032a83f3a29aa3a3aff@fake-sentry.io:65535/2147483647'.
[Debug 00:00:00.24]: Starting BackgroundWorker.
[Debug 00:00:00.24]: BackgroundWorker Started.
[Debug 00:00:00.25]: New scope pushed.
[Debug 00:00:00.25]: Registering integration: 'AutoSessionTrackingIntegration'.
[Debug 00:00:00.25]: Registering integration: 'AppDomainUnhandledExceptionIntegration'.
[Debug 00:00:00.25]: Registering integration: 'AppDomainProcessExitIntegration'.
[Debug 00:00:00.25]: Registering integration: 'UnobservedTaskExceptionIntegration'.
[Debug 00:00:00.25]: Registering integration: 'SentryDiagnosticListenerIntegration'.
[Debug 00:00:00.25]: Registering SQL Client integration.
[Debug 00:00:00.26]: Failed to report an error on a session because there is none active.
[Info 00:00:00.26]: Capturing event.
[Debug 00:00:00.26]: Running processor on exception: my exception
[Debug 00:00:00.27]: Creating SentryStackTrace. isCurrentStackTrace: False.
[Debug 00:00:00.28]: Running main event processor on: Event d1883ee892f64c1893a38ba4ea143d14
[Debug 00:00:00.29]: Enqueuing envelope d1883ee892f64c1893a38ba4ea143d14
[Info 00:00:00.29]: Envelope queued up: 'd1883ee892f64c1893a38ba4ea143d14'
[Debug 00:00:00.29]: Envelope handed off to transport (event ID: 'd1883ee892f64c1893a38ba4ea143d14'). 1 items in queue.
[Debug 00:00:00.29]: De-queueing event d1883ee892f64c1893a38ba4ea143d14
[Debug 00:00:00.40]: Registering EF Core integration
[Debug 00:00:01.41]: Enqueuing envelope 4941f11c6b1243659c215a94fc680c19
[Info 00:00:01.41]: Envelope queued up: '4941f11c6b1243659c215a94fc680c19'
[Debug 00:00:01.41]: Envelope handed off to transport (event ID: '4941f11c6b1243659c215a94fc680c19'). 1 items in queue.
[Info 00:00:01.41]: Disposing the Hub.
[Debug 00:00:01.41]: De-queueing event 4941f11c6b1243659c215a94fc680c19
[Debug 00:00:01.41]: Successfully flushed all events up to call to FlushAsync.

@mattjohnsonpint mattjohnsonpint enabled auto-merge (squash) December 2, 2022 02:30
@mattjohnsonpint mattjohnsonpint merged commit de3cf72 into main Dec 2, 2022
@mattjohnsonpint mattjohnsonpint deleted the diagnosticsource branch December 2, 2022 02:44
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

Automatic SQL Instrumentation Unable to Find Spans
2 participants