Log Connection.Open() duration (#3977)

* Log Connection.Open() duration

* Added read-only

* space

* Fix tests

* comment

src/Microsoft.Health.Fhir.SqlServer/Features/Search/SqlServerSearchService.cs

@@ -542,6 +542,7 @@ await _sqlRetryService.ExecuteSql(
                         }
                     }
                 },
+                _logger,
                 cancellationToken,
                 true); // this enables reads from replicas
             return searchResult;

src/Microsoft.Health.Fhir.SqlServer/Features/Storage/SqlRetry/ISqlRetryService.cs

@@ -16,7 +16,7 @@ public interface ISqlRetryService
     {
         Task TryLogEvent(string process, string status, string text, DateTime? startDate, CancellationToken cancellationToken);
 
-        Task ExecuteSql(Func<SqlConnection, CancellationToken, SqlException, Task> action, CancellationToken cancellationToken, bool isReadOnly = false);
+        Task ExecuteSql<TLogger>(Func<SqlConnection, CancellationToken, SqlException, Task> action, ILogger<TLogger> logger, CancellationToken cancellationToken, bool isReadOnly = false);
 
         Task ExecuteSql<TLogger>(SqlCommand sqlCommand, Func<SqlCommand, CancellationToken, Task> action, ILogger<TLogger> logger, string logMessage, CancellationToken cancellationToken, bool isReadOnly = false, bool disableRetries = false);
 

src/Microsoft.Health.Fhir.SqlServer/Features/Storage/SqlRetry/SqlRetryService.cs

@@ -6,6 +6,7 @@
 using System;
 using System.Collections.Generic;
 using System.Data;
+using System.Diagnostics;
 using System.Threading;
 using System.Threading.Tasks;
 using EnsureThat;
@@ -199,12 +200,14 @@ private bool IsRetriable(Exception ex)
         /// Executes delegate <paramref name="action"/> and retries it's execution if retriable error is encountered error.
         /// In the case if non-retriable exception or if the last retry failed tha same exception is thrown.
         /// </summary>
+        /// <typeparam name="TLogger">Type used for the <paramref name="logger"/>. <see cref="ILogger{TCategoryName}"/></typeparam>
         /// <param name="action">Delegate to be executed.</param>
+        /// <param name="logger">Logger used on first try error (or retry error) and connection open.</param>
         /// <param name="cancellationToken">Cancellation token.</param>
         /// <param name="isReadOnly">"Flag indicating whether connection to read only replica can be used."</param>
         /// <returns>A task representing the asynchronous operation.</returns>
         /// <exception>When executing this method, if exception is thrown that is not retriable or if last retry fails, then same exception is thrown by this method.</exception>
-        public async Task ExecuteSql(Func<SqlConnection, CancellationToken, SqlException, Task> action, CancellationToken cancellationToken, bool isReadOnly = false)
+        public async Task ExecuteSql<TLogger>(Func<SqlConnection, CancellationToken, SqlException, Task> action, ILogger<TLogger> logger, CancellationToken cancellationToken, bool isReadOnly = false)
         {
             EnsureArg.IsNotNull(action, nameof(action));
 
@@ -215,7 +218,7 @@ public async Task ExecuteSql(Func<SqlConnection, CancellationToken, SqlException
             {
                 try
                 {
-                    using SqlConnection sqlConnection = await _replicaHandler.GetConnection(_sqlConnectionBuilder, isReadOnly, cancellationToken);
+                    using SqlConnection sqlConnection = await _replicaHandler.GetConnection(_sqlConnectionBuilder, isReadOnly, logger, cancellationToken);
                     await action(sqlConnection, cancellationToken, sqlException);
                     return;
                 }
@@ -244,7 +247,7 @@ public async Task ExecuteSql(Func<SqlConnection, CancellationToken, SqlException
         /// <typeparam name="TLogger">Type used for the <paramref name="logger"/>. <see cref="ILogger{TCategoryName}"/></typeparam>
         /// <param name="sqlCommand">SQL command to be executed.</param>
         /// <param name="action">Delegate to be executed by passing <paramref name="sqlCommand"/> as input parameter.</param>
-        /// <param name="logger">Logger used on first try error or retry error.</param>
+        /// <param name="logger">Logger used on first try error (or retry error) and connection open.</param>
         /// <param name="logMessage">Message to be logged on error.</param>
         /// <param name="cancellationToken">Cancellation token.</param>
         /// <param name="isReadOnly">"Flag indicating whether connection to read only replica can be used."</param>
@@ -268,7 +271,7 @@ public async Task ExecuteSql<TLogger>(SqlCommand sqlCommand, Func<SqlCommand, Ca
             {
                 try
                 {
-                    using SqlConnection sqlConnection = await _replicaHandler.GetConnection(_sqlConnectionBuilder, isReadOnly, cancellationToken);
+                    using SqlConnection sqlConnection = await _replicaHandler.GetConnection(_sqlConnectionBuilder, isReadOnly, logger, cancellationToken);
                     //// only change if not default 30 seconds. This should allow to handle any explicitly set timeouts correctly.
                     sqlCommand.CommandTimeout = sqlCommand.CommandTimeout == 30 ? _commandTimeout : sqlCommand.CommandTimeout;
                     sqlCommand.Connection = sqlConnection;
@@ -432,9 +435,11 @@ public ReplicaHandler()
             {
             }
 
-            public async Task<SqlConnection> GetConnection(ISqlConnectionBuilder sqlConnectionBuilder, bool isReadOnly, CancellationToken cancel)
+            public async Task<SqlConnection> GetConnection<TLogger>(ISqlConnectionBuilder sqlConnectionBuilder, bool isReadOnly, ILogger<TLogger> logger, CancellationToken cancel)
             {
                 SqlConnection conn;
+                var sw = Stopwatch.StartNew();
+                var isReadOnlyConnection = isReadOnly ? "read-only " : string.Empty;
                 if (!isReadOnly)
                 {
                     conn = await sqlConnectionBuilder.GetSqlConnectionAsync(initialCatalog: null, cancellationToken: cancel).ConfigureAwait(false);
@@ -445,6 +450,7 @@ public async Task<SqlConnection> GetConnection(ISqlConnectionBuilder sqlConnecti
 
                     if (replicaTrafficRatio < 0.5) // it does not make sense to use replica less than master at all
                     {
+                        isReadOnlyConnection = string.Empty;
                         conn = await sqlConnectionBuilder.GetSqlConnectionAsync(initialCatalog: null, cancellationToken: cancel).ConfigureAwait(false);
                     }
                     else if (replicaTrafficRatio > 0.99)
@@ -454,6 +460,11 @@ public async Task<SqlConnection> GetConnection(ISqlConnectionBuilder sqlConnecti
                     else
                     {
                         var useWriteConnection = unchecked(Interlocked.Increment(ref _usageCounter)) % (int)(1 / (1 - _replicaTrafficRatio)) == 1; // examples for ratio -> % divider = { 0.9 -> 10, 0.8 -> 5, 0.75 - 4, 0.67 - 3, 0.5 -> 2, <0.5 -> 1}
+                        if (useWriteConnection)
+                        {
+                            isReadOnlyConnection = string.Empty;
+                        }
+
                         conn = useWriteConnection
                                 ? await sqlConnectionBuilder.GetSqlConnectionAsync(initialCatalog: null, cancellationToken: cancel).ConfigureAwait(false)
                                 : await sqlConnectionBuilder.GetReadOnlySqlConnectionAsync(initialCatalog: null, cancellationToken: cancel).ConfigureAwait(false);
@@ -464,6 +475,7 @@ public async Task<SqlConnection> GetConnection(ISqlConnectionBuilder sqlConnecti
                 // must be set before opening connection to take effect. Therefore we must reset it to null here before opening the connection.
                 conn.RetryLogicProvider = null; // To remove this line _sqlConnectionBuilder in healthcare-shared-components must be modified.
                 await conn.OpenAsync(cancel);
+                logger.LogInformation($"Opened {isReadOnlyConnection}connection to the database in {sw.Elapsed.TotalSeconds} seconds.");
 
                 return conn;
             }

test/Microsoft.Health.Fhir.Shared.Tests.Integration/Persistence/SqlRetryServiceTests.cs

@@ -5,6 +5,7 @@
 
 using System;
 using System.Collections.Generic;
+using System.Linq;
 using System.Threading;
 using System.Threading.Tasks;
 using Microsoft.Data.SqlClient;
@@ -393,6 +394,8 @@ private async Task SingleConnectionRetryTest(Func<string, string, Task> testStor
                     Assert.Equal(i + 1, result[i]);
                 }
 
+                logger.LogRecords.RemoveAll(_ => _.Exception == null);
+
                 Assert.Single(logger.LogRecords);
 
                 Assert.Equal(LogLevel.Information, logger.LogRecords[0].LogLevel);
@@ -435,6 +438,8 @@ await sqlRetryService.ExecuteReaderAsync<long, SqlRetryService>(
                     Assert.True(IsConnectionFailedException(ex, testConnectionInitializationFailure));
                 }
 
+                logger.LogRecords.RemoveAll(_ => _.Exception == null);
+
                 Assert.Equal(3, logger.LogRecords.Count);
 
                 Assert.Equal(LogLevel.Information, logger.LogRecords[0].LogLevel);
@@ -488,6 +493,8 @@ await sqlRetryService.ExecuteSql(
                         CancellationToken.None);
                 }
 
+                Assert.Contains("Opened", logger.LogRecords[0].Message); // Check that logging of connection open was logged.
+                logger.LogRecords.RemoveAll(_ => _.Exception == null);
                 Assert.Single(logger.LogRecords);
 
                 Assert.Equal(LogLevel.Information, logger.LogRecords[0].LogLevel);
@@ -532,6 +539,7 @@ private async Task AllRetriesFailTest(int sqlErrorNumber, Func<string, string, T
                 }
 
                 Assert.Equal(sqlErrorNumber, ex.Number);
+                logger.LogRecords.RemoveAll(_ => _.Exception == null);
                 Assert.Equal(3, logger.LogRecords.Count);
 
                 Assert.Equal(LogLevel.Information, logger.LogRecords[0].LogLevel);
@@ -715,7 +723,7 @@ public void Log<TState>(
                 Exception exception,
                 Func<TState, Exception, string> formatter)
             {
-                LogRecords.Add(new LogRecord() { LogLevel = logLevel, Exception = exception });
+                LogRecords.Add(new LogRecord() { LogLevel = logLevel, Exception = exception, Message = formatter(state, exception) });
             }
 
             public bool IsEnabled(LogLevel logLevel)
@@ -728,6 +736,8 @@ internal class LogRecord
                 internal LogLevel LogLevel { get; init; }
 
                 internal Exception Exception { get; init; }
+
+                internal string Message { get; init; }
             }
         }
     }