[Work in Progress] SqlException State 35

src/Microsoft.Health.SqlServer/Features/Client/SqlConnectionWrapper.cs

@@ -9,8 +9,10 @@
 using System.Threading.Tasks;
 using EnsureThat;
 using Microsoft.Data.SqlClient;
+using Microsoft.Extensions.Logging;
 using Microsoft.Health.SqlServer.Configs;
 using Microsoft.Health.SqlServer.Features.Storage;
+using Polly;
 
 namespace Microsoft.Health.SqlServer.Features.Client;
 
@@ -21,25 +23,32 @@ public class SqlConnectionWrapper : IDisposable
     private readonly ISqlConnectionBuilder _sqlConnectionBuilder;
     private readonly SqlRetryLogicBaseProvider _sqlRetryLogicBaseProvider;
     private readonly SqlServerDataStoreConfiguration _sqlServerDataStoreConfiguration;
+    private readonly ILogger<SqlConnectionWrapper> _logger;
+
+    private const int RetryAttempts = 3;
+    private static readonly TimeSpan RetrySleepDuration = TimeSpan.FromSeconds(2);
 
     internal SqlConnectionWrapper(
         SqlTransactionHandler sqlTransactionHandler,
         ISqlConnectionBuilder connectionBuilder,
         SqlRetryLogicBaseProvider sqlRetryLogicBaseProvider,
         bool enlistInTransactionIfPresent,
-        SqlServerDataStoreConfiguration sqlServerDataStoreConfiguration)
+        SqlServerDataStoreConfiguration sqlServerDataStoreConfiguration,
+        ILogger<SqlConnectionWrapper> logger)
     {
         EnsureArg.IsNotNull(sqlTransactionHandler, nameof(sqlTransactionHandler));
         EnsureArg.IsNotNull(connectionBuilder, nameof(connectionBuilder));
         EnsureArg.IsNotNull(sqlRetryLogicBaseProvider, nameof(sqlRetryLogicBaseProvider));
         EnsureArg.IsNotNull(sqlServerDataStoreConfiguration, nameof(sqlServerDataStoreConfiguration));
+        EnsureArg.IsNotNull(logger, nameof(logger));
 
         _sqlServerDataStoreConfiguration = EnsureArg.IsNotNull(sqlServerDataStoreConfiguration, nameof(sqlServerDataStoreConfiguration));
 
         _sqlTransactionHandler = sqlTransactionHandler;
         _enlistInTransactionIfPresent = enlistInTransactionIfPresent;
         _sqlConnectionBuilder = connectionBuilder;
         _sqlRetryLogicBaseProvider = sqlRetryLogicBaseProvider;
+        _logger = logger;
     }
 
     public SqlConnection SqlConnection { get; private set; }
@@ -64,7 +73,7 @@ internal async Task InitializeAsync(string initialCatalog = null, CancellationTo
 
         if (SqlConnection.State != ConnectionState.Open)
         {
-            await SqlConnection.OpenAsync(cancellationToken).ConfigureAwait(false);
+            await OpenRetriableSqlConnectionAsync(cancellationToken).ConfigureAwait(false);
         }
 
         if (_enlistInTransactionIfPresent && _sqlTransactionHandler.SqlTransactionScope != null)
@@ -78,6 +87,34 @@ internal async Task InitializeAsync(string initialCatalog = null, CancellationTo
         }
     }
 
+    /// <summary>
+    /// Open sql connection which is retried up to 3 times if <see cref="SqlException"/> is caught with state 35.
+    /// <remarks>
+    /// Retries have been added to cater to the following exception:
+    /// "A connection was successfully established with the server, but then an error occurred during the login process.
+    /// (provider: TCP Provider, error: 35 - An internal exception was caught)"
+    /// </remarks>
+    /// </summary>
+    /// <param name="cancellationToken">Cancellation Token.</param>
+    private async Task OpenRetriableSqlConnectionAsync(CancellationToken cancellationToken)
+    {
+        int attempts = 1;
+
+        await Policy.Handle<SqlException>(se => se.State == 35)
+        .WaitAndRetryAsync(
+            retryCount: RetryAttempts,
+            sleepDurationProvider: (retryCount) => RetrySleepDuration,
+            onRetry: (exception, retryCount) =>
+            {
+                _logger.LogWarning(
+                    exception,
+                    "Attempt {Attempt} of {MaxAttempts} to open Sql connection.",
+                    attempts++,
+                    RetryAttempts);
+            })
+        .ExecuteAsync(token => SqlConnection.OpenAsync(token), cancellationToken).ConfigureAwait(false);
+    }
+
     [Obsolete("Please use " + nameof(CreateRetrySqlCommand) + " or " + nameof(CreateNonRetrySqlCommand) + " instead.")]
     public SqlCommandWrapper CreateSqlCommand()
     {

src/Microsoft.Health.SqlServer/Features/Client/SqlConnectionWrapperFactory.cs

@@ -8,6 +8,7 @@
 using System.Threading.Tasks;
 using EnsureThat;
 using Microsoft.Data.SqlClient;
+using Microsoft.Extensions.Logging;
 using Microsoft.Extensions.Options;
 using Microsoft.Health.SqlServer.Configs;
 using Microsoft.Health.SqlServer.Features.Storage;
@@ -20,27 +21,29 @@ public class SqlConnectionWrapperFactory
     private readonly ISqlConnectionBuilder _sqlConnectionBuilder;
     private readonly SqlRetryLogicBaseProvider _sqlRetryLogicBaseProvider;
     private readonly SqlServerDataStoreConfiguration _sqlServerDataStoreConfiguration;
+    private readonly ILoggerFactory _loggerFactory;
+
+    private readonly ILogger<SqlConnectionWrapper> _sqlConnectionWrapperLogger;
 
     public SqlConnectionWrapperFactory(
         SqlTransactionHandler sqlTransactionHandler,
         ISqlConnectionBuilder sqlConnectionBuilder,
         SqlRetryLogicBaseProvider sqlRetryLogicBaseProvider,
-        IOptions<SqlServerDataStoreConfiguration> sqlServerDataStoreConfiguration)
+        IOptions<SqlServerDataStoreConfiguration> sqlServerDataStoreConfiguration,
+        ILoggerFactory loggerFactory)
     {
-        EnsureArg.IsNotNull(sqlTransactionHandler, nameof(sqlTransactionHandler));
-        EnsureArg.IsNotNull(sqlConnectionBuilder, nameof(sqlConnectionBuilder));
-        EnsureArg.IsNotNull(sqlRetryLogicBaseProvider, nameof(sqlRetryLogicBaseProvider));
-
+        _sqlTransactionHandler = EnsureArg.IsNotNull(sqlTransactionHandler, nameof(sqlTransactionHandler));
+        _sqlConnectionBuilder = EnsureArg.IsNotNull(sqlConnectionBuilder, nameof(sqlConnectionBuilder));
+        _sqlRetryLogicBaseProvider = EnsureArg.IsNotNull(sqlRetryLogicBaseProvider, nameof(sqlRetryLogicBaseProvider));
         _sqlServerDataStoreConfiguration = EnsureArg.IsNotNull(sqlServerDataStoreConfiguration?.Value, nameof(sqlServerDataStoreConfiguration));
-        _sqlTransactionHandler = sqlTransactionHandler;
-        _sqlConnectionBuilder = sqlConnectionBuilder;
-        _sqlRetryLogicBaseProvider = sqlRetryLogicBaseProvider;
+        _loggerFactory = EnsureArg.IsNotNull(loggerFactory, nameof(loggerFactory));
+        _sqlConnectionWrapperLogger = _loggerFactory.CreateLogger<SqlConnectionWrapper>();
     }
 
     [SuppressMessage("Reliability", "CA2000:Dispose objects before losing scope", Justification = "Callers are responsible for disposal.")]
     public async Task<SqlConnectionWrapper> ObtainSqlConnectionWrapperAsync(CancellationToken cancellationToken, bool enlistInTransaction = false)
     {
-        var sqlConnectionWrapper = new SqlConnectionWrapper(_sqlTransactionHandler, _sqlConnectionBuilder, _sqlRetryLogicBaseProvider, enlistInTransaction, _sqlServerDataStoreConfiguration);
+        var sqlConnectionWrapper = new SqlConnectionWrapper(_sqlTransactionHandler, _sqlConnectionBuilder, _sqlRetryLogicBaseProvider, enlistInTransaction, _sqlServerDataStoreConfiguration, _sqlConnectionWrapperLogger);
         await sqlConnectionWrapper.InitializeAsync(cancellationToken: cancellationToken).ConfigureAwait(false);
 
         return sqlConnectionWrapper;
@@ -49,7 +52,7 @@ public async Task<SqlConnectionWrapper> ObtainSqlConnectionWrapperAsync(Cancella
     [SuppressMessage("Reliability", "CA2000:Dispose objects before losing scope", Justification = "Callers are responsible for disposal.")]
     public async Task<SqlConnectionWrapper> ObtainSqlConnectionWrapperAsync(string initialCatalog, CancellationToken cancellationToken, bool enlistInTransaction = false)
     {
-        var sqlConnectionWrapper = new SqlConnectionWrapper(_sqlTransactionHandler, _sqlConnectionBuilder, _sqlRetryLogicBaseProvider, enlistInTransaction, _sqlServerDataStoreConfiguration);
+        var sqlConnectionWrapper = new SqlConnectionWrapper(_sqlTransactionHandler, _sqlConnectionBuilder, _sqlRetryLogicBaseProvider, enlistInTransaction, _sqlServerDataStoreConfiguration, _sqlConnectionWrapperLogger);
         await sqlConnectionWrapper.InitializeAsync(initialCatalog, cancellationToken: cancellationToken).ConfigureAwait(false);
 
         return sqlConnectionWrapper;

src/Microsoft.Health.SqlServer/Registration/SqlServerBaseRegistrationExtensions.cs

@@ -1,4 +1,4 @@
-// -------------------------------------------------------------------------------------------------
+// -------------------------------------------------------------------------------------------------
 // Copyright (c) Microsoft Corporation. All rights reserved.
 // Licensed under the MIT License (MIT). See LICENSE in the repo root for license information.
 // -------------------------------------------------------------------------------------------------
@@ -101,6 +101,7 @@ public static IServiceCollection AddSqlServerConnection(this IServiceCollection
         // TODO: Does SqlTransactionHandler need to be registered directly? Should usage change to ITransactionHandler?
         Func<IServiceProvider, SqlTransactionHandler> handlerFactory = p => p.GetRequiredService<SqlTransactionHandler>();
 
+        services.AddLogging();
         services.TryAddScoped<SqlConnectionWrapperFactory>();
         services.TryAddScoped<SqlTransactionHandler>();
         services.TryAddScoped<ITransactionHandler>(handlerFactory);

test/Microsoft.Health.SqlServer.Tests.Integration/Features/Schema/Manager/BaseSchemaRunnerTests.cs

@@ -32,7 +32,7 @@ public BaseSchemaRunnerTests(ITestOutputHelper output)
         var sqlConnection = new DefaultSqlConnectionBuilder(ConnectionStringProvider, SqlConfigurableRetryFactory.CreateNoneRetryProvider());
         SqlRetryLogicBaseProvider sqlRetryLogicBaseProvider = SqlConfigurableRetryFactory.CreateFixedRetryProvider(new SqlClientRetryOptions().Settings);
 
-        var sqlConnectionWrapperFactory = new SqlConnectionWrapperFactory(_sqlTransactionHandler, sqlConnection, sqlRetryLogicBaseProvider, options);
+        var sqlConnectionWrapperFactory = new SqlConnectionWrapperFactory(_sqlTransactionHandler, sqlConnection, sqlRetryLogicBaseProvider, options, NullLoggerFactory.Instance);
         _dataStore = new SchemaManagerDataStore(sqlConnectionWrapperFactory, options, NullLogger<SchemaManagerDataStore>.Instance);
 
         _runner = new BaseSchemaRunner(sqlConnectionWrapperFactory, _dataStore, ConnectionStringProvider, NullLogger<BaseSchemaRunner>.Instance);

test/Microsoft.Health.SqlServer.Tests.Integration/Features/Schema/SchemaUpgradeRunnerTests.cs

@@ -41,7 +41,7 @@ public override async Task InitializeAsync()
         var config = Options.Create(new SqlServerDataStoreConfiguration());
 
         SqlRetryLogicBaseProvider sqlRetryLogicBaseProvider = SqlConfigurableRetryFactory.CreateFixedRetryProvider(new SqlClientRetryOptions().Settings);
-        var sqlConnectionWrapperFactory = new SqlConnectionWrapperFactory(_sqlTransactionHandler, sqlConnection, sqlRetryLogicBaseProvider, config);
+        var sqlConnectionWrapperFactory = new SqlConnectionWrapperFactory(_sqlTransactionHandler, sqlConnection, sqlRetryLogicBaseProvider, config, NullLoggerFactory.Instance);
 
         _schemaDataStore = new SchemaManagerDataStore(sqlConnectionWrapperFactory, config, NullLogger<SchemaManagerDataStore>.Instance);
         _runner = new SchemaUpgradeRunner(new ScriptProvider<SchemaVersion>(), new BaseScriptProvider(), NullLogger<SchemaUpgradeRunner>.Instance, sqlConnectionWrapperFactory, _schemaDataStore);

test/Microsoft.Health.SqlServer.Tests.Integration/SqlIntegrationTestBase.cs

@@ -8,6 +8,7 @@
 using System.Threading;
 using System.Threading.Tasks;
 using Microsoft.Data.SqlClient;
+using Microsoft.Extensions.Logging.Abstractions;
 using Microsoft.Extensions.Options;
 using Microsoft.Health.SqlServer.Configs;
 using Microsoft.Health.SqlServer.Features.Client;
@@ -63,7 +64,8 @@ public virtual async Task InitializeAsync()
             TransactionHandler,
             new DefaultSqlConnectionBuilder(ConnectionStringProvider, SqlConfigurableRetryFactory.CreateNoneRetryProvider()),
             SqlConfigurableRetryFactory.CreateFixedRetryProvider(new SqlClientRetryOptions().Settings),
-            options);
+            options,
+            NullLoggerFactory.Instance);
 
         ConnectionWrapper = await ConnectionFactory.ObtainSqlConnectionWrapperAsync("master", CancellationToken.None).ConfigureAwait(false);