Merge | Enable SqlClientDiagnosticListener in SqlCommand on .NET Framework

[edwardneal]

Description

This picks up where #3493 left off. Now that the SqlCommand methods with instrumentation have been merged, I've enabled the SqlClientDiagnosticListener functionality on the class.

I also noticed that tests in the DiagnosticTest class were passing unexpectedly, so dug a little deeper. These tests currently verify that the diagnostics we receive have a valid structure, but don't verify that we receive all of the diagnostics we expect to. I've modified the test to tighten this logic and explicitly specify the diagnostics we expect each scenario to receive.

@benrr101 I think we've passed the point where I'm likely to generate merge conflicts, but I'm happy to re-merge if you think that's likely.

Issues

Contributes to #1261.

Testing

Automated tests pass (even with the stricter validation.) Could someone run CI please?

[paulmedynski]

/azp run

[azure-pipelines]

Azure Pipelines successfully started running 2 pipeline(s).

[codecov]

Codecov Report

✅ All modified and coverable lines are covered by tests.
✅ Project coverage is 70.20%. Comparing base (b555adf) to head (7b51d80).
⚠️ Report is 17 commits behind head on main.

❗ There is a different number of reports uploaded between BASE (b555adf) and HEAD (7b51d80). Click for more details.

HEAD has 1 upload less than BASE

Flag	BASE (b555adf)	HEAD (7b51d80)
addons	1	0

Additional details and impacted files

@@             Coverage Diff             @@
##             main    #3658       +/-   ##
===========================================
- Coverage   90.82%   70.20%   -20.62%     
===========================================
  Files           6      268      +262     
  Lines         316    45338    +45022     
===========================================
+ Hits          287    31829    +31542     
- Misses         29    13509    +13480     

Flag	Coverage Δ
addons	?
netcore	71.05% <100.00%> (?)
netfx	70.52% <100.00%> (?)

Flags with carried forward coverage won't be shown. Click here to find out more.

☔ View full report in Codecov by Sentry.
📢 Have feedback on the report? Share it here.

🚀 New features to boost your workflow:

• ❄️ Test Analytics: Detect flaky tests, report on failures, and find test suite problems.

[paulmedynski]

@edwardneal - I'm seeing failures in these new diagnostics you added in my Authentication PR:

https://sqlclientdrivers.visualstudio.com/public/_build/results?buildId=127793&view=logs&j=68f8cc34-f2c7-5b7e-c405-ea6eb73ea4dc&t=e8a47cea-45d5-51aa-b70a-e05e7376b156&s=c583459b-5840-5c74-26fb-70fbf416e683

Do you think these changes could be sensitive to timing or environment? I'll re-run the failing tests again, but this is the second time they've failed in this pipeline run, both times in .NET 8 on ARM64.

[edwardneal]

Yes, possibly; the failing tests are ConnectionOpenAsyncErrorTest and ConnectionOpenAsyncTest, and these failures are (very loosely) correlated to multiple tests running in parallel. These wouldn't have failed previously because the tests didn't actually check that downstream DiagnosticListener instances received the diagnostics they expected to.

Have you seen any failures in the sync variants? I can see a measure of sync-over-async in the tests which wait for RemoteExecutor, so maybe we're left waiting on threads unnecessarily. If that's the cause, then I'd test changing the RemoteExecutor.Invoke methods to take an async lambda expression which awaits CollectStatisticsDiagnosticsAsync rather than calling Wait() on the task it returns.

[paulmedynski]

The entire ManualTests assembly disables parallel test execution:

https://github.com/dotnet/SqlClient/blob/main/src/Microsoft.Data.SqlClient/tests/ManualTests/XUnitAssemblyAttributes.cs

I don't think there are any tests running in parallel here. I can make your suggested changes to see if that helps anyway though. The failures seem to only be when testing via MDS <PackageReference>, which is interesting.

[edwardneal]

That's interesting. Lines 480-494 of the linked logs show that tests are overlapping.

  Test: ExecuteScalarAsyncErrorTest Enabled Listeners
  Test: ExecuteScalarAsyncErrorTest Started Server
    Passed Microsoft.Data.SqlClient.ManualTesting.Tests.MetricsTest.PooledConnectionsCounters_Functional [178 ms]
    Passed Microsoft.Data.SqlClient.ManualTesting.Tests.MetricsTest.NonPooledConnectionsCounters_Functional [562 ms]
    Passed Microsoft.Data.SqlClient.ManualTesting.Tests.MetricsTest.StasisCounters_Functional [169 ms]
    Passed Microsoft.Data.SqlClient.ManualTesting.Tests.MetricsTest.ConnectionPoolGroupsCounter_Functional [117 ms]
  Test: ExecuteScalarAsyncErrorTest SqlOperation Successful
  Test: ExecuteScalarAsyncErrorTest Listeners Disabled
  Test: ExecuteScalarAsyncErrorTest Server Disposed
  Test: ExecuteScalarAsyncErrorTest Listeners Disposed Successfully
  Test: ConnectionOpenAsyncErrorTest Enabled Listeners
  Test: ConnectionOpenAsyncErrorTest Started Server
    Passed Microsoft.Data.SqlClient.ManualTesting.Tests.DiagnosticTest.ExecuteScalarAsyncErrorTest [682 ms]
  Test: ConnectionOpenAsyncErrorTest SqlOperation Successful
  Unhandled exception. System.AggregateException: One or more errors occurred. (Missing diagnostic 'Microsoft.Data.SqlClient.WriteConnectionOpenError')

We can see that four extra tests start and finish in the time it takes to proceed with ExecuteScalarAsyncErrorTest, and this test hasn't yet finished before ConnectionOpenAsyncErrorTest starts.

Perhaps it simply takes some time for the console output from the child process to be flushed from the parent. I don't think that's necessarily the issue (I can see a similar pattern in ConnectionOpenErrorTest, which succeeds) but it's a little confusing.