Pruning timer not disposed even after disposing all SqlConnection instances

[a510]

Bug Description

I'm not sure if this is a bug or by-design but the trace log keeps showing this message once I use SqlConnection and even after disposing it.

20:02:52.463|[AdvancedTrace]|<prov.DbConnectionFactory.PruneConnectionPoolGroups|RES|INFO|CPOOL> 1
20:03:22.468|[AdvancedTrace]|<prov.DbConnectionFactory.PruneConnectionPoolGroups|RES|INFO|CPOOL> 1
20:03:52.464|[AdvancedTrace]|<prov.DbConnectionFactory.PruneConnectionPoolGroups|RES|INFO|CPOOL> 1
20:04:22.476|[AdvancedTrace]|<prov.DbConnectionFactory.PruneConnectionPoolGroups|RES|INFO|CPOOL> 1
20:04:52.472|[AdvancedTrace]|<prov.DbConnectionFactory.PruneConnectionPoolGroups|RES|INFO|CPOOL> 1
...

To reproduce

Run this code with trace logging enabled.

var connection = new SqlConnection(conStr);
connection.Open();
connection.Dispose();

Console.ReadLine();

Expected behavior

The prune stops when there's no more pools and the timer is disposed.

Further technical details

Microsoft.Data.SqlClient version: 5.0.1
.NET target: (dotnet 7.0)

[lcheunglci]

Hi @a510, thanks for bringing this to our attention and providing the repro steps. We'll take a look soon.

[lcheunglci]

If you desire to dispose a connection, you should disable connection pooling or there also a method SqlConnection.ClearAllPools for cleaning all the connections.

[a510]

Thanks @lcheunglci, but even with this code the timer is still running.

var connection = new SqlConnection("...;Pooling=False;");
connection.Open();
connection.Dispose();
SqlConnection.ClearAllPools();
Console.ReadLine();

[lcheunglci]

When invoking SqlConnection.ClearAllPools(), it invokes Shutdown from the pool group which calls Dispose for the timer and should be logging <prov.DbConnectionPool.Shutdown|RES|INFO|CPOOL> in the process.

[a510]

Not this message => <prov.DbConnectionPool.Shutdown|RES|INFO|CPOOL>.
I mean this message => <prov.DbConnectionFactory.PruneConnectionPoolGroups|RES|INFO|CPOOL>
It's being logged every 30 seconds forever, whether I call ClearAllPools or not.

Here's an excerpt of the log:
(note the 4 minutes gap before this happens)

...
18:55:49.878|[SNIScopeEnter]|<prov.DbConnectionFactory.ClearAllPools|API.ClearAllPools | INFO | SCOPE | Entering Scope 118:55:49.879|[ScopeLeave]|Exit Scope 1
18:59:48.131|[AdvancedTrace]|<prov.DbConnectionFactory.PruneConnectionPoolGroups|RES|INFO|CPOOL> 1
18:59:48.131|[Trace]|<prov.DbConnectionPoolGroup.ClearInternal|RES|INFO|CPOOL> 1, Idle
19:00:18.129|[AdvancedTrace]|<prov.DbConnectionFactory.PruneConnectionPoolGroups|RES|INFO|CPOOL> 1
19:00:18.131|[Trace]|<prov.DbConnectionPoolGroup.ReadyToRemove|RES|INFO|CPOOL> 1, Disabled
19:00:18.138|[Trace]|<prov.DbConnectionFactory.QueuePoolGroupForRelease|RES|INFO|CPOOL> 1, poolGroup=1
19:00:48.133|[AdvancedTrace]|<prov.DbConnectionFactory.PruneConnectionPoolGroups|RES|INFO|CPOOL> 1
19:00:48.141|[AdvancedTrace]|<prov.DbConnectionFactory.PruneConnectionPoolGroups|RES|INFO|CPOOL> 1, ReleasePoolGroup=1
19:01:18.129|[AdvancedTrace]|<prov.DbConnectionFactory.PruneConnectionPoolGroups|RES|INFO|CPOOL> 1
19:01:48.132|[AdvancedTrace]|<prov.DbConnectionFactory.PruneConnectionPoolGroups|RES|INFO|CPOOL> 1
19:02:18.138|[AdvancedTrace]|<prov.DbConnectionFactory.PruneConnectionPoolGroups|RES|INFO|CPOOL> 1
19:02:48.131|[AdvancedTrace]|<prov.DbConnectionFactory.PruneConnectionPoolGroups|RES|INFO|CPOOL> 1
19:03:18.123|[AdvancedTrace]|<prov.DbConnectionFactory.PruneConnectionPoolGroups|RES|INFO|CPOOL> 1
19:03:48.132|[AdvancedTrace]|<prov.DbConnectionFactory.PruneConnectionPoolGroups|RES|INFO|CPOOL> 1
19:04:18.133|[AdvancedTrace]|<prov.DbConnectionFactory.PruneConnectionPoolGroups|RES|INFO|CPOOL> 1
19:04:48.126|[AdvancedTrace]|<prov.DbConnectionFactory.PruneConnectionPoolGroups|RES|INFO|CPOOL> 1
19:05:18.123|[AdvancedTrace]|<prov.DbConnectionFactory.PruneConnectionPoolGroups|RES|INFO|CPOOL> 1
19:05:48.135|[AdvancedTrace]|<prov.DbConnectionFactory.PruneConnectionPoolGroups|RES|INFO|CPOOL> 1
19:06:18.123|[AdvancedTrace]|<prov.DbConnectionFactory.PruneConnectionPoolGroups|RES|INFO|CPOOL> 1
19:06:48.132|[AdvancedTrace]|<prov.DbConnectionFactory.PruneConnectionPoolGroups|RES|INFO|CPOOL> 1
19:07:18.130|[AdvancedTrace]|<prov.DbConnectionFactory.PruneConnectionPoolGroups|RES|INFO|CPOOL> 1
19:07:48.131|[AdvancedTrace]|<prov.DbConnectionFactory.PruneConnectionPoolGroups|RES|INFO|CPOOL> 1
19:08:18.131|[AdvancedTrace]|<prov.DbConnectionFactory.PruneConnectionPoolGroups|RES|INFO|CPOOL> 1
19:08:48.120|[AdvancedTrace]|<prov.DbConnectionFactory.PruneConnectionPoolGroups|RES|INFO|CPOOL> 1
19:09:18.131|[AdvancedTrace]|<prov.DbConnectionFactory.PruneConnectionPoolGroups|RES|INFO|CPOOL> 1
19:09:48.128|[AdvancedTrace]|<prov.DbConnectionFactory.PruneConnectionPoolGroups|RES|INFO|CPOOL> 1
19:10:18.126|[AdvancedTrace]|<prov.DbConnectionFactory.PruneConnectionPoolGroups|RES|INFO|CPOOL> 1
19:10:48.136|[AdvancedTrace]|<prov.DbConnectionFactory.PruneConnectionPoolGroups|RES|INFO|CPOOL> 1
19:11:18.132|[AdvancedTrace]|<prov.DbConnectionFactory.PruneConnectionPoolGroups|RES|INFO|CPOOL> 1
19:11:48.133|[AdvancedTrace]|<prov.DbConnectionFactory.PruneConnectionPoolGroups|RES|INFO|CPOOL> 1
19:12:18.130|[AdvancedTrace]|<prov.DbConnectionFactory.PruneConnectionPoolGroups|RES|INFO|CPOOL> 1
19:12:48.128|[AdvancedTrace]|<prov.DbConnectionFactory.PruneConnectionPoolGroups|RES|INFO|CPOOL> 1
19:13:18.132|[AdvancedTrace]|<prov.DbConnectionFactory.PruneConnectionPoolGroups|RES|INFO|CPOOL> 1
19:13:48.130|[AdvancedTrace]|<prov.DbConnectionFactory.PruneConnectionPoolGroups|RES|INFO|CPOOL> 1
19:14:18.124|[AdvancedTrace]|<prov.DbConnectionFactory.PruneConnectionPoolGroups|RES|INFO|CPOOL> 1
19:14:48.134|[AdvancedTrace]|<prov.DbConnectionFactory.PruneConnectionPoolGroups|RES|INFO|CPOOL> 1
19:15:18.136|[AdvancedTrace]|<prov.DbConnectionFactory.PruneConnectionPoolGroups|RES|INFO|CPOOL> 1
19:15:48.137|[AdvancedTrace]|<prov.DbConnectionFactory.PruneConnectionPoolGroups|RES|INFO|CPOOL> 1
19:16:18.129|[AdvancedTrace]|<prov.DbConnectionFactory.PruneConnectionPoolGroups|RES|INFO|CPOOL> 1
...

[lcheunglci]

Thanks for the logs, I'll re-open the issue and investigate this further after our release

[JRahnama]

@a510 what is the connection time out in the connection string?

[a510]

This is the connection string:

"Server=tcp:blahblah.database.windows.net,1433;Database=blahblah;User ID=blahblah;Password=blahblah;Connection Timeout=30;Pooling=False;"