add extra logging (Azure#918)

Author: MaddyDev

src/SqlBindingUtilities.cs

@@ -386,11 +386,16 @@ public static async Task<ServerProperties> GetServerTelemetryProperties(SqlConne
         /// <param name="cmd">The SqlCommand being executed</param>
         /// <param name="logger">The logger</param>
         /// <param name="cancellationToken">The cancellation token to pass to the call</param>
+        /// <param name="logCommand">Defaults to false and when set logs the command being executed</param>
         /// <returns>The result of the call</returns>
-        public static async Task<object> ExecuteScalarAsyncWithLogging(this SqlCommand cmd, ILogger logger, CancellationToken cancellationToken)
+        public static async Task<object> ExecuteScalarAsyncWithLogging(this SqlCommand cmd, ILogger logger, CancellationToken cancellationToken, bool logCommand = false)
         {
             try
             {
+                if (logCommand)
+                {
+                    logger.LogDebug($"Executing query={cmd.CommandText}");
+                }
                 return await cmd.ExecuteScalarAsync(cancellationToken);
             }
             catch (Exception e)
@@ -406,11 +411,16 @@ public static async Task<object> ExecuteScalarAsyncWithLogging(this SqlCommand c
         /// <param name="cmd">The SqlCommand being executed</param>
         /// <param name="logger">The logger</param>
         /// <param name="cancellationToken">The cancellation token to pass to the call</param>
+        /// <param name="logCommand">Defaults to false and when set logs the command being executed</param>
         /// <returns>The result of the call</returns>
-        public static async Task<int> ExecuteNonQueryAsyncWithLogging(this SqlCommand cmd, ILogger logger, CancellationToken cancellationToken)
+        public static async Task<int> ExecuteNonQueryAsyncWithLogging(this SqlCommand cmd, ILogger logger, CancellationToken cancellationToken, bool logCommand = false)
         {
             try
             {
+                if (logCommand)
+                {
+                    logger.LogDebug($"Executing query={cmd.CommandText}");
+                }
                 return await cmd.ExecuteNonQueryAsync(cancellationToken);
             }
             catch (Exception e)
@@ -426,11 +436,16 @@ public static async Task<int> ExecuteNonQueryAsyncWithLogging(this SqlCommand cm
         /// <param name="cmd">The SqlCommand being executed</param>
         /// <param name="logger">The logger</param>
         /// <param name="cancellationToken">The cancellation token to pass to the call</param>
+        /// <param name="logCommand">Defaults to false and when set logs the command being executed</param>
         /// <returns>The result of the call</returns>
-        public static async Task<SqlDataReader> ExecuteReaderAsyncWithLogging(this SqlCommand cmd, ILogger logger, CancellationToken cancellationToken)
+        public static async Task<SqlDataReader> ExecuteReaderAsyncWithLogging(this SqlCommand cmd, ILogger logger, CancellationToken cancellationToken, bool logCommand = false)
         {
             try
             {
+                if (logCommand)
+                {
+                    logger.LogDebug($"Executing query={cmd.CommandText}");
+                }
                 return await cmd.ExecuteReaderAsync(cancellationToken);
             }
             catch (Exception e)

src/TriggerBinding/SqlTableChangeMonitor.cs

@@ -284,7 +284,7 @@ private async Task GetTableChangesAsync(SqlConnection connection, CancellationTo
                         using (SqlCommand updateTablesPreInvocationCommand = this.BuildUpdateTablesPreInvocation(connection, transaction))
                         {
                             var commandSw = Stopwatch.StartNew();
-                            await updateTablesPreInvocationCommand.ExecuteNonQueryAsyncWithLogging(this._logger, token);
+                            await updateTablesPreInvocationCommand.ExecuteNonQueryAsyncWithLogging(this._logger, token, true);
                             setLastSyncVersionDurationMs = commandSw.ElapsedMilliseconds;
                         }
 
@@ -510,7 +510,7 @@ private async Task RenewLeasesAsync(SqlConnection connection, CancellationToken
                         {
                             var stopwatch = Stopwatch.StartNew();
 
-                            int rowsAffected = await renewLeasesCommand.ExecuteNonQueryAsyncWithLogging(this._logger, token);
+                            int rowsAffected = await renewLeasesCommand.ExecuteNonQueryAsyncWithLogging(this._logger, token, true);
 
                             long durationMs = stopwatch.ElapsedMilliseconds;
 
@@ -613,7 +613,7 @@ private async Task ReleaseLeasesAsync(SqlConnection connection, CancellationToke
                             using (SqlCommand releaseLeasesCommand = this.BuildReleaseLeasesCommand(connection, transaction))
                             {
                                 var commandSw = Stopwatch.StartNew();
-                                int rowsUpdated = await releaseLeasesCommand.ExecuteNonQueryAsyncWithLogging(this._logger, token);
+                                int rowsUpdated = await releaseLeasesCommand.ExecuteNonQueryAsyncWithLogging(this._logger, token, true);
                                 releaseLeasesDurationMs = commandSw.ElapsedMilliseconds;
                             }
 

src/TriggerBinding/SqlTriggerMetricsProvider.cs

@@ -66,7 +66,7 @@ private async Task<long> GetUnprocessedChangeCountAsync()
                             using (SqlCommand getUnprocessedChangesCommand = this.BuildGetUnprocessedChangesCommand(connection, transaction, primaryKeyColumns, userTableId))
                             {
                                 var commandSw = Stopwatch.StartNew();
-                                unprocessedChangeCount = (long)await getUnprocessedChangesCommand.ExecuteScalarAsyncWithLogging(this._logger, CancellationToken.None);
+                                unprocessedChangeCount = (long)await getUnprocessedChangesCommand.ExecuteScalarAsyncWithLogging(this._logger, CancellationToken.None, true);
                                 getUnprocessedChangesDurationMs = commandSw.ElapsedMilliseconds;
                             }