Pooled connection ramp up slow when using "Active Directory Default" authentication

[ascott18]

Describe the bug

I have a web application that uses Hangfire w/ SQL server storage. On startup, Hangfire spawns many worker threads, each of which needs a database connection.

I'm using "Active Directory Default" as the authentication method against an Azure SQL Database. When running on localhost, it spends quite a while making failed requests to Azure IMDS before falling back on using other methods. In my case, the configured authentication source is Visual Studio.

When a lot of connections are opened at once (at app startup), many of them time out. Timeouts are never hit using username/password auth.

System.InvalidOperationException: Timeout expired.  The timeout period elapsed prior to obtaining a connection from the pool.  This may have occurred because all pooled connections were in use and max pool size was reached.
   at Microsoft.Data.ProviderBase.DbConnectionFactory.TryGetConnection(DbConnection owningConnection, TaskCompletionSource`1 retry, DbConnectionOptions userOptions, DbConnectionInternal oldConnection, DbConnectionInternal& connection)     
   at Microsoft.Data.ProviderBase.DbConnectionInternal.TryOpenConnectionInternal(DbConnection outerConnection, DbConnectionFactory connectionFactory, TaskCompletionSource`1 retry, DbConnectionOptions userOptions)
   at Microsoft.Data.ProviderBase.DbConnectionClosed.TryOpenConnection(DbConnection outerConnection, DbConnectionFactory connectionFactory, TaskCompletionSource`1 retry, DbConnectionOptions userOptions)
   at Microsoft.Data.SqlClient.SqlConnection.TryOpen(TaskCompletionSource`1 retry, SqlConnectionOverrides overrides)
   at Microsoft.Data.SqlClient.SqlConnection.Open(SqlConnectionOverrides overrides)
   at Microsoft.Data.SqlClient.SqlConnection.Open()
   at Program.<>c__DisplayClass0_1.<<Main>$>b__0() in C:\src\aaaRepros\sql-azure-auth-timeout\Program.cs:line 14
   at System.Threading.Thread.StartCallback()

To reproduce

Run the following, once with Active Directory Default, and once with username/password auth.

For me, username/password established 20 connections in 8 seconds. AAD did 12 connections in ~15 seconds, and then the rest timed out. Password auth was therefore about 3x faster.

using Microsoft.Data.SqlClient;

var connString = "Server=tcp:REDACTED.database.windows.net,1433;Authentication=Active Directory Default";

var threads = new List<Thread>();
for (int i = 0; i < 20; i++)
{
    var num = i;
    var thread = new Thread(() => {
        var connection = new SqlConnection(connString);
        Console.WriteLine($"{num} connecting");
        connection.Open();
        Console.WriteLine($"{num} connected");
        // Simulate doing work.
        Thread.Sleep(30000);
    });
    threads.Add(thread);
}

foreach (var thread in threads) {
    thread.Start();
}

foreach (var thread in threads) {
    thread.Join();
}

Output from Repro

1/13/2022 3:38:23 PM: 09 connecting
1/13/2022 3:38:23 PM: 18 connecting
1/13/2022 3:38:23 PM: 06 connecting
1/13/2022 3:38:23 PM: 17 connecting
1/13/2022 3:38:23 PM: 16 connecting
1/13/2022 3:38:23 PM: 15 connecting
1/13/2022 3:38:23 PM: 12 connecting
1/13/2022 3:38:23 PM: 19 connecting
1/13/2022 3:38:23 PM: 02 connecting
1/13/2022 3:38:23 PM: 00 connecting
1/13/2022 3:38:23 PM: 07 connecting
1/13/2022 3:38:23 PM: 04 connecting
1/13/2022 3:38:23 PM: 14 connecting
1/13/2022 3:38:23 PM: 05 connecting
1/13/2022 3:38:23 PM: 10 connecting
1/13/2022 3:38:23 PM: 08 connecting
1/13/2022 3:38:23 PM: 11 connecting
1/13/2022 3:38:23 PM: 03 connecting
1/13/2022 3:38:23 PM: 13 connecting
1/13/2022 3:38:23 PM: 01 connecting
1/13/2022 3:38:24 PM: 08 connected
1/13/2022 3:38:26 PM: 12 connected
1/13/2022 3:38:27 PM: 18 connected
1/13/2022 3:38:28 PM: 04 connected
1/13/2022 3:38:29 PM: 06 connected
1/13/2022 3:38:31 PM: 07 connected
1/13/2022 3:38:32 PM: 14 connected
1/13/2022 3:38:33 PM: 09 connected
1/13/2022 3:38:34 PM: 01 connected
1/13/2022 3:38:35 PM: 03 connected
1/13/2022 3:38:37 PM: 11 connected
Unhandled exception. Unhandled exception. Unhandled exception.Unhandled exception. Unhandled exception. Unhandled exception.Unhandled exception. Unhandled exception.   1/13/2022 3:38:38 PM: 15 connected
System.InvalidOperationException: Timeout expired.  The timeout period elapsed prior to obtaining a connection from the pool.  This may have occurred because all pooled connections were in use and max pool size was reached.
   at Microsoft.Data.ProviderBase.DbConnectionFactory.TryGetConnection(DbConnection owningConnection, TaskCompletionSource`1 retry, DbConnectionOptions userOptions, DbConnectionInternal oldConnection, DbConnectionInternal& connection)     
   at Microsoft.Data.ProviderBase.DbConnectionInternal.TryOpenConnectionInternal(DbConnection outerConnection, DbConnectionFactory connectionFactory, TaskCompletionSource`1 retry, DbConnectionOptions userOptions)
   at Microsoft.Data.ProviderBase.DbConnectionClosed.TryOpenConnection(DbConnection outerConnection, DbConnectionFactory connectionFactory, TaskCompletionSource`1 retry, DbConnectionOptions userOptions)
   at Microsoft.Data.SqlClient.SqlConnection.TryOpen(TaskCompletionSource`1 retry, SqlConnectionOverrides overrides)
   at Microsoft.Data.SqlClient.SqlConnection.Open(SqlConnectionOverrides overrides)
   at Microsoft.Data.SqlClient.SqlConnection.Open()
   at Program.<>c__DisplayClass0_1.<<Main>$>b__0() in C:\src\aaaRepros\sql-azure-auth-timeout\Program.cs:line 13
   at System.Threading.Thread.StartCallback()
System.InvalidOperationException: Timeout expired.  The timeout period elapsed prior to obtaining a connection from the pool.  This may have occurred because all pooled connections were in use and max pool size was reached.
   at Microsoft.Data.ProviderBase.DbConnectionFactory.TryGetConnection(DbConnection owningConnection, TaskCompletionSource`1 retry, DbConnectionOptions userOptions, DbConnectionInternal oldConnection, DbConnectionInternal& connection)     
   at Microsoft.Data.ProviderBase.DbConnectionInternal.TryOpenConnectionInternal(DbConnection outerConnection, DbConnectionFactory connectionFactory, TaskCompletionSource`1 retry, DbConnectionOptions userOptions)
   at Microsoft.Data.ProviderBase.DbConnectionClosed.TryOpenConnection(DbConnection outerConnection, DbConnectionFactory connectionFactory, TaskCompletionSource`1 retry, DbConnectionOptions userOptions)
   at Microsoft.Data.SqlClient.SqlConnection.TryOpen(TaskCompletionSource`1 retry, SqlConnectionOverrides overrides)
   at Microsoft.Data.SqlClient.SqlConnection.Open(SqlConnectionOverrides overrides)
   at Microsoft.Data.SqlClient.SqlConnection.Open()
   at Program.<>c__DisplayClass0_1.<<Main>$>b__0() in C:\src\aaaRepros\sql-azure-auth-timeout\Program.cs:line 13
   at System.Threading.Thread.StartCallback()System.InvalidOperationException: Timeout expired.  The timeout period elapsed prior to obtaining a connection from the pool.  This may have occurred because all pooled connections were in use and max pool size was reached.
   at Microsoft.Data.ProviderBase.DbConnectionFactory.TryGetConnection(DbConnection owningConnection, TaskCompletionSource`1 retry, DbConnectionOptions userOptions, DbConnectionInternal oldConnection, DbConnectionInternal& connection)     
   at Microsoft.Data.ProviderBase.DbConnectionInternal.TryOpenConnectionInternal(DbConnection outerConnection, DbConnectionFactory connectionFactory, TaskCompletionSource`1 retry, DbConnectionOptions userOptions)
   at Microsoft.Data.ProviderBase.DbConnectionClosed.TryOpenConnection(DbConnection outerConnection, DbConnectionFactory connectionFactory, TaskCompletionSource`1 retry, DbConnectionOptions userOptions)
   at Microsoft.Data.SqlClient.SqlConnection.TryOpen(TaskCompletionSource`1 retry, SqlConnectionOverrides overrides)
   at Microsoft.Data.SqlClient.SqlConnection.Open(SqlConnectionOverrides overrides)
   at Microsoft.Data.SqlClient.SqlConnection.Open()
   at Program.<>c__DisplayClass0_1.<<Main>$>b__0() in C:\src\aaaRepros\sql-azure-auth-timeout\Program.cs:line 13
   at System.Threading.Thread.StartCallback()
System.InvalidOperationException: Timeout expired.  The timeout period elapsed prior to obtaining a connection from the pool.  This may have occurred because all pooled connections were in use and max pool size was reached.
   at Microsoft.Data.ProviderBase.DbConnectionFactory.TryGetConnection(DbConnection owningConnection, TaskCompletionSource`1 retry, DbConnectionOptions userOptions, DbConnectionInternal oldConnection, DbConnectionInternal& connection)     
   at Microsoft.Data.ProviderBase.DbConnectionInternal.TryOpenConnectionInternal(DbConnection outerConnection, DbConnectionFactory connectionFactory, TaskCompletionSource`1 retry, DbConnectionOptions userOptions)
   at Microsoft.Data.ProviderBase.DbConnectionClosed.TryOpenConnection(DbConnection outerConnection, DbConnectionFactory connectionFactory, TaskCompletionSource`1 retry, DbConnectionOptions userOptions)
   at Microsoft.Data.SqlClient.SqlConnection.TryOpen(TaskCompletionSource`1 retry, SqlConnectionOverrides overrides)
   at Microsoft.Data.SqlClient.SqlConnection.Open(SqlConnectionOverrides overrides)
   at Microsoft.Data.SqlClient.SqlConnection.Open()
   at Program.<>c__DisplayClass0_1.<<Main>$>b__0() in C:\src\aaaRepros\sql-azure-auth-timeout\Program.cs:line 13
   at System.Threading.Thread.StartCallback()
System.InvalidOperationException: Timeout expired.  The timeout period elapsed prior to obtaining a connection from the pool.  This may have occurred because all pooled connections were in use and max pool size was reached.
   at Microsoft.Data.ProviderBase.DbConnectionFactory.TryGetConnection(DbConnection owningConnection, TaskCompletionSource`1 retry, DbConnectionOptions userOptions, DbConnectionInternal oldConnection, DbConnectionInternal& connection)     
   at Microsoft.Data.ProviderBase.DbConnectionInternal.TryOpenConnectionInternal(DbConnection outerConnection, DbConnectionFactory connectionFactory, TaskCompletionSource`1 retry, DbConnectionOptions userOptions)
   at Microsoft.Data.ProviderBase.DbConnectionClosed.TryOpenConnection(DbConnection outerConnection, DbConnectionFactory connectionFactory, TaskCompletionSource`1 retry, DbConnectionOptions userOptions)
   at Microsoft.Data.SqlClient.SqlConnection.TryOpen(TaskCompletionSource`1 retry, SqlConnectionOverrides overrides)
   at Microsoft.Data.SqlClient.SqlConnection.Open(SqlConnectionOverrides overrides)
   at Microsoft.Data.SqlClient.SqlConnection.Open()
   at Program.<>c__DisplayClass0_1.<<Main>$>b__0() in C:\src\aaaRepros\sql-azure-auth-timeout\Program.cs:line 13
   at System.Threading.Thread.StartCallback()
System.InvalidOperationException: Timeout expired.  The timeout period elapsed prior to obtaining a connection from the pool.  This may have occurred because all pooled connections were in use and max pool size was reached.
   at Microsoft.Data.ProviderBase.DbConnectionFactory.TryGetConnection(DbConnection owningConnection, TaskCompletionSource`1 retry, DbConnectionOptions userOptions, DbConnectionInternal oldConnection, DbConnectionInternal& connection)     
   at Microsoft.Data.ProviderBase.DbConnectionInternal.TryOpenConnectionInternal(DbConnection outerConnection, DbConnectionFactory connectionFactory, TaskCompletionSource`1 retry, DbConnectionOptions userOptions)
   at Microsoft.Data.ProviderBase.DbConnectionClosed.TryOpenConnection(DbConnection outerConnection, DbConnectionFactory connectionFactory, TaskCompletionSource`1 retry, DbConnectionOptions userOptions)
   at Microsoft.Data.SqlClient.SqlConnection.TryOpen(TaskCompletionSource`1 retry, SqlConnectionOverrides overrides)
   at Microsoft.Data.SqlClient.SqlConnection.Open(SqlConnectionOverrides overrides)
   at Microsoft.Data.SqlClient.SqlConnection.Open()
   at Program.<>c__DisplayClass0_1.<<Main>$>b__0() in C:\src\aaaRepros\sql-azure-auth-timeout\Program.cs:line 13
   at System.Threading.Thread.StartCallback()System.InvalidOperationException: Timeout expired.  The timeout period elapsed prior to obtaining a connection from the pool.  This may have occurred because all pooled connections were in use and max pool size was reached.
   at Microsoft.Data.ProviderBase.DbConnectionFactory.TryGetConnection(DbConnection owningConnection, TaskCompletionSource`1 retry, DbConnectionOptions userOptions, DbConnectionInternal oldConnection, DbConnectionInternal& connection)     
   at Microsoft.Data.ProviderBase.DbConnectionInternal.TryOpenConnectionInternal(DbConnection outerConnection, DbConnectionFactory connectionFactory, TaskCompletionSource`1 retry, DbConnectionOptions userOptions)
   at Microsoft.Data.ProviderBase.DbConnectionClosed.TryOpenConnection(DbConnection outerConnection, DbConnectionFactory connectionFactory, TaskCompletionSource`1 retry, DbConnectionOptions userOptions)
   at Microsoft.Data.SqlClient.SqlConnection.TryOpen(TaskCompletionSource`1 retry, SqlConnectionOverrides overrides)
   at Microsoft.Data.SqlClient.SqlConnection.Open(SqlConnectionOverrides overrides)
   at Microsoft.Data.SqlClient.SqlConnection.Open()
   at Program.<>c__DisplayClass0_1.<<Main>$>b__0() in C:\src\aaaRepros\sql-azure-auth-timeout\Program.cs:line 13
   at System.Threading.Thread.StartCallback()
System.InvalidOperationException: Timeout expired.  The timeout period elapsed prior to obtaining a connection from the pool.  This may have occurred because all pooled connections were in use and max pool size was reached.
   at Microsoft.Data.ProviderBase.DbConnectionFactory.TryGetConnection(DbConnection owningConnection, TaskCompletionSource`1 retry, DbConnectionOptions userOptions, DbConnectionInternal oldConnection, DbConnectionInternal& connection)     
   at Microsoft.Data.ProviderBase.DbConnectionInternal.TryOpenConnectionInternal(DbConnection outerConnection, DbConnectionFactory connectionFactory, TaskCompletionSource`1 retry, DbConnectionOptions userOptions)
   at Microsoft.Data.ProviderBase.DbConnectionClosed.TryOpenConnection(DbConnection outerConnection, DbConnectionFactory connectionFactory, TaskCompletionSource`1 retry, DbConnectionOptions userOptions)
   at Microsoft.Data.SqlClient.SqlConnection.TryOpen(TaskCompletionSource`1 retry, SqlConnectionOverrides overrides)
   at Microsoft.Data.SqlClient.SqlConnection.Open(SqlConnectionOverrides overrides)
   at Microsoft.Data.SqlClient.SqlConnection.Open()
   at Program.<>c__DisplayClass0_1.<<Main>$>b__0() in C:\src\aaaRepros\sql-azure-auth-timeout\Program.cs:line 13
   at System.Threading.Thread.StartCallback()

Expected behavior

Using Azure authentication does not cause connection ramp-up to be 3x slower.

Further technical details

Microsoft.Data.SqlClient version: (found on the nuget or Microsoft.Data.SqlClient.dll) 4.0.0
.NET target: (e.g. Framework 4.7.1, Core 2.2.2) 6.0.1
SQL Server version: (e.g. SQL Server 2017) Azure SQL Database
Operating system: (e.g. Windows 2019, Ubuntu 18.04, macOS 10.13, Docker container) Windows 10

Additional context
Add any other context about the problem here.

[JRahnama]

Is it AAD username password or just regular username /password?

[ascott18]

Regular SQL Server username/password (as the server admin user, for example).

[JRahnama]

@ascott18 Isn't it expected? Acquiring token is a time consuming process from AAD server and it takes some time when it runs for the first time, but when first token is acquired the process is expedited as the token is cached and being reused.

[ascott18]

@JRahnama Token caching/reuse doesn't appear to be happening. Connections after the first connection don't seem to happen any faster than the first. See the collapsed "Output from Repro" in my first post.

There doesn't seem to be any parallelization in spawning pooled connections. A single thread opening 20 connections can open them with the exact same speed as 20 threads each opening one connection. Is this intended? I'd be curious to know why, if so. Is it an intentional throttle on the connection pool to prevent the pool's connection count from spiking? If that's the case, perhaps the throttle period could be made to discount the time spent on acquiring the auth token.

[davidhendrickmb]

Did you ever find a resolution to this? I am experiencing the same issues connecting via Entity Framework Core and Visual Studio.

[David-Engel]

The connection pooler opens connections serially, by design. There is caching of access tokens within a pool, but the cache is only checked before a connection request is sent to the pooler. So 20 simultaneous connections will not benefit from that cache. If you "warm up the pool" first by opening one connection before calling open on any others, subsequent connections will get the cached token and should be opened much faster.

We do have an opportunity to improve MDS here, though, by caching tokens from the underlying library used by Active Directory Default.

[David-Engel]

Addressed in #2380