Microsoft.Data.SqlClient.SqlException (0x80131904): Connection Timeout Expired. The timeout period elapsed during the post-login phase

Question

I am seeing the following exception occur sporadically in my logs:

   Microsoft.Data.SqlClient.SqlException (0x80131904): Connection Timeout Expired.  The timeout period elapsed during the post-login phase.  The connection could have timed out while waiting for server to complete the login process and respond; Or it could have timed out while attempting to create multiple active connections.  The duration spent while attempting to connect to this server was - [Pre-Login] initialization=29; handshake=12; [Login] initialization=0; authentication=0; [Post-Login] complete=14042;   
    ---> System.ComponentModel.Win32Exception (258): The wait operation timed out.  
      at Microsoft.Data.ProviderBase.DbConnectionPool.CheckPoolBlockingPeriod(Exception e)  
      at Microsoft.Data.ProviderBase.DbConnectionPool.CreateObject(DbConnection owningObject, DbConnectionOptions userOptions, DbConnectionInternal oldConnection)  
      at Microsoft.Data.ProviderBase.DbConnectionPool.UserCreateRequest(DbConnection owningObject, DbConnectionOptions userOptions, DbConnectionInternal oldConnection)  
      at Microsoft.Data.ProviderBase.DbConnectionPool.TryGetConnection(DbConnection owningObject, UInt32 waitForMultipleObjectsTimeout, Boolean allowCreate, Boolean onlyOneCheckConnection, DbConnectionOptions userOptions, DbConnectionInternal& connection)  
      at Microsoft.Data.ProviderBase.DbConnectionPool.WaitForPendingOpen()  
   \--- End of stack trace from previous location ---  
      at Microsoft.EntityFrameworkCore.Storage.RelationalConnection.OpenInternalAsync(Boolean errorsExpected, CancellationToken cancellationToken)  
      at Microsoft.EntityFrameworkCore.Storage.RelationalConnection.OpenInternalAsync(Boolean errorsExpected, CancellationToken cancellationToken)  
      at Microsoft.EntityFrameworkCore.Storage.RelationalConnection.OpenAsync(CancellationToken cancellationToken, Boolean errorsExpected)  
      at Microsoft.EntityFrameworkCore.Storage.RelationalCommand.ExecuteReaderAsync(RelationalCommandParameterObject parameterObject, CancellationToken cancellationToken)  
      at Microsoft.EntityFrameworkCore.Query.Internal.SingleQueryingEnumerable`1.AsyncEnumerator.InitializeReaderAsync(AsyncEnumerator enumerator, CancellationToken cancellationToken)  
      at Microsoft.EntityFrameworkCore.SqlServer.Storage.Internal.SqlServerExecutionStrategy.ExecuteAsync[TState,TResult](TState state, Func`4 operation, Func`4 verifySucceeded, CancellationToken cancellationToken)  
      at Microsoft.EntityFrameworkCore.Query.Internal.SingleQueryingEnumerable`1.AsyncEnumerator.MoveNextAsync()  
   ClientConnectionId:68875bad-5437-4292-957b-f00c83d3eb4b  
   Error Number:-2,State:0,Class:11  

This seems to be a similar question, and I am curious if this is the same issue that I am encountering:
https://stackoverflow.com/questions/21230927/sql-azure-the-timeout-period-elapsed-during-the-post-login-phase

One of the answers suggests that it is due to Auto-Pause. Right now I do not have a lot of traffic, but what little traffic I do get does cause SQL activity. I am perplexed by this exception and would like to get further context/suggestions on how to address it.

What sticks out to me is the [Post-Login] complete=14042... does that mean seconds? As in 14042 seconds? That is 3.9 hours and I am curious how a connection can stay open that long, and why. I am disposing of all my EFCore connections immediately after creating them, so this doesn't make sense to me.

Thank you for any assistance/context/insight you can provide,
Michael

Answer 1

Please run the following query and let’s try to find evidence about the Azure SQL Database being throttled.

SELECT *  
FROM sys.dm_db_resource_stats  
ORDER BY end_time DESC;  

If you see avg_log_write_percent is close or equal 100% you need to scale up the tier of the database.

What about the DTU graph on the portal? Please verify if consumption of resources is reaching the limits of the tier since you added the data sync process.

You can run the following query also to verify throttling occurs.

SELECT       
(COUNT(end_time) - SUM(CASE WHEN avg_cpu_percent > 80 THEN 1 ELSE 0 END) * 1.0) / COUNT(end_time) AS 'CPU Fit Percent',  
(COUNT(end_time) - SUM(CASE WHEN avg_log_write_percent > 80 THEN 1 ELSE 0 END) * 1.0) / COUNT(end_time) AS 'Log Write Fit Percent',  
(COUNT(end_time) - SUM(CASE WHEN avg_data_io_percent > 80 THEN 1 ELSE 0 END) * 1.0) / COUNT(end_time) AS 'Physical Data Read Fit Percent'  
FROM sys.dm_db_resource_stats  
--service level objective (SLO) of 99.9% <= go to next tier  

When avg_log_write_percent is at 100% or near 100% then throttling occurs.

Auto-pause only occurs if the database is an Azure Serverless database, the other Azure SQL flavors do not support auto-pause.

On this documentation you will find ways to troubleshoot this error.

Answer 2

After 30 minutes idle connections are dropped. Please read here for more details. That is normal on Azure SQL.

Answer 3

Seeing this exception just now, wonder if they are related:

   System.InvalidOperationException: An exception has been raised that is likely due to a transient failure. Consider enabling transient error resiliency by adding 'EnableRetryOnFailure' to the 'UseSqlServer' call.  
    ---> Microsoft.Data.SqlClient.SqlException (0x80131904): A transport-level error has occurred when receiving results from the server. (provider: TCP Provider, error: 0 - The semaphore timeout period has expired.)  
    ---> System.ComponentModel.Win32Exception (121): The semaphore timeout period has expired.  
      at Microsoft.Data.SqlClient.SqlCommand.<>c.<ExecuteDbDataReaderAsync>b__208_0(Task`1 result)  
      at System.Threading.Tasks.ContinuationResultTaskFromResultTask`2.InnerInvoke()  
      at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state)  
   \--- End of stack trace from previous location ---  
      at System.Threading.Tasks.Task.ExecuteWithThreadLocal(Task& currentTaskSlot, Thread threadPoolThread)  
   \--- End of stack trace from previous location ---  
      at Microsoft.EntityFrameworkCore.Storage.RelationalCommand.ExecuteReaderAsync(RelationalCommandParameterObject parameterObject, CancellationToken cancellationToken)  
      at Microsoft.EntityFrameworkCore.Storage.RelationalCommand.ExecuteReaderAsync(RelationalCommandParameterObject parameterObject, CancellationToken cancellationToken)  
      at Microsoft.EntityFrameworkCore.Query.Internal.SingleQueryingEnumerable`1.AsyncEnumerator.InitializeReaderAsync(AsyncEnumerator enumerator, CancellationToken cancellationToken)  
      at Microsoft.EntityFrameworkCore.SqlServer.Storage.Internal.SqlServerExecutionStrategy.ExecuteAsync[TState,TResult](TState state, Func`4 operation, Func`4 verifySucceeded, CancellationToken cancellationToken)  
   ClientConnectionId:a2d90377-5b45-47a0-8938-93a550499a32  
   Error Number:121,State:0,Class:20  
      --- End of inner exception stack trace ---  
      at Microsoft.EntityFrameworkCore.SqlServer.Storage.Internal.SqlServerExecutionStrategy.ExecuteAsync[TState,TResult](TState state, Func`4 operation, Func`4 verifySucceeded, CancellationToken cancellationToken)  
      at Microsoft.EntityFrameworkCore.Query.Internal.SingleQueryingEnumerable`1.AsyncEnumerator.MoveNextAsync()  

I'd hate to have to add EnableRetryOnFailure when I already have retry functionality in place. Not sure of the repercussions of doing so.