Fix logs

Author: Charles-Gagnon

src/TriggerBinding/SqlTableChangeMonitor.cs

@@ -189,17 +189,17 @@ public void Dispose()
         /// </summary>
         private async Task RunChangeConsumptionLoopAsync()
         {
-            this._logger.LogInformationWithThreadId($"Starting change consumption loop. MaxBatchSize: {this._maxBatchSize} PollingIntervalMs: {this._pollingIntervalInMs}");
+            this._logger.LogInformation($"Starting change consumption loop. MaxBatchSize: {this._maxBatchSize} PollingIntervalMs: {this._pollingIntervalInMs}");
 
             try
             {
                 CancellationToken token = this._cancellationTokenSourceCheckForChanges.Token;
 
                 using (var connection = new SqlConnection(this._connectionString))
                 {
-                    this._logger.LogDebugWithThreadId("BEGIN OpenChangeConsumptionConnection");
+                    this._logger.LogDebug("BEGIN OpenChangeConsumptionConnection");
                     await connection.OpenAsync(token);
-                    this._logger.LogDebugWithThreadId("END OpenChangeConsumptionConnection");
+                    this._logger.LogDebug("END OpenChangeConsumptionConnection");
 
                     bool forceReconnect = false;
                     // Check for cancellation request only after a cycle of checking and processing of changes completes.
@@ -216,7 +216,7 @@ private async Task RunChangeConsumptionLoopAsync()
                         {
                             forceReconnect = false;
                         }
-                        this._logger.LogDebugWithThreadId($"BEGIN ProcessingChanges State={this._state}");
+                        this._logger.LogDebug($"BEGIN ProcessingChanges State={this._state}");
 
                         try
                         {
@@ -243,8 +243,8 @@ private async Task RunChangeConsumptionLoopAsync()
                             this._logger.LogError($"Fatal SQL Client exception processing changes. Will attempt to reestablish connection in {this._pollingIntervalInMs}ms. Exception = {e.Message}");
                             forceReconnect = true;
                         }
-                        this._logger.LogDebugWithThreadId("END ProcessingChanges");
-                        this._logger.LogDebugWithThreadId($"Delaying for {this._pollingIntervalInMs}ms");
+                        this._logger.LogDebug("END ProcessingChanges");
+                        this._logger.LogDebug($"Delaying for {this._pollingIntervalInMs}ms");
                         await Task.Delay(TimeSpan.FromMilliseconds(this._pollingIntervalInMs), token);
                     }
                 }
@@ -276,7 +276,7 @@ private async Task RunChangeConsumptionLoopAsync()
         /// </summary>
         private async Task GetTableChangesAsync(SqlConnection connection, CancellationToken token)
         {
-            this._logger.LogDebugWithThreadId("BEGIN GetTableChanges");
+            this._logger.LogDebug("BEGIN GetTableChanges");
             try
             {
                 var transactionSw = Stopwatch.StartNew();
@@ -289,19 +289,19 @@ private async Task GetTableChangesAsync(SqlConnection connection, CancellationTo
                         // Update the version number stored in the global state table if necessary before using it.
                         using (SqlCommand updateTablesPreInvocationCommand = this.BuildUpdateTablesPreInvocation(connection, transaction))
                         {
-                            this._logger.LogDebugWithThreadId($"BEGIN UpdateTablesPreInvocation Query={updateTablesPreInvocationCommand.CommandText}");
+                            this._logger.LogDebug($"BEGIN UpdateTablesPreInvocation Query={updateTablesPreInvocationCommand.CommandText}");
                             var commandSw = Stopwatch.StartNew();
                             await updateTablesPreInvocationCommand.ExecuteNonQueryAsync(token);
                             setLastSyncVersionDurationMs = commandSw.ElapsedMilliseconds;
                         }
-                        this._logger.LogDebugWithThreadId($"END UpdateTablesPreInvocation Duration={setLastSyncVersionDurationMs}ms");
+                        this._logger.LogDebug($"END UpdateTablesPreInvocation Duration={setLastSyncVersionDurationMs}ms");
 
                         var rows = new List<IReadOnlyDictionary<string, object>>();
 
                         // Use the version number to query for new changes.
                         using (SqlCommand getChangesCommand = this.BuildGetChangesCommand(connection, transaction))
                         {
-                            this._logger.LogDebugWithThreadId($"BEGIN GetChanges Query={getChangesCommand.CommandText}");
+                            this._logger.LogDebug($"BEGIN GetChanges Query={getChangesCommand.CommandText}");
                             var commandSw = Stopwatch.StartNew();
 
                             using (SqlDataReader reader = await getChangesCommand.ExecuteReaderAsync(token))
@@ -314,19 +314,19 @@ private async Task GetTableChangesAsync(SqlConnection connection, CancellationTo
 
                             getChangesDurationMs = commandSw.ElapsedMilliseconds;
                         }
-                        this._logger.LogDebugWithThreadId($"END GetChanges Duration={getChangesDurationMs}ms ChangedRows={rows.Count}");
+                        this._logger.LogDebug($"END GetChanges Duration={getChangesDurationMs}ms ChangedRows={rows.Count}");
 
                         // If changes were found, acquire leases on them.
                         if (rows.Count > 0)
                         {
                             using (SqlCommand acquireLeasesCommand = this.BuildAcquireLeasesCommand(connection, transaction, rows))
                             {
-                                this._logger.LogDebugWithThreadId($"BEGIN AcquireLeases Query={acquireLeasesCommand.CommandText}");
+                                this._logger.LogDebug($"BEGIN AcquireLeases Query={acquireLeasesCommand.CommandText}");
                                 var commandSw = Stopwatch.StartNew();
                                 await acquireLeasesCommand.ExecuteNonQueryAsync(token);
                                 acquireLeasesDurationMs = commandSw.ElapsedMilliseconds;
                             }
-                            this._logger.LogDebugWithThreadId($"END AcquireLeases Duration={acquireLeasesDurationMs}ms");
+                            this._logger.LogDebug($"END AcquireLeases Duration={acquireLeasesDurationMs}ms");
 
                             // Only send event if we got changes to reduce the overall number of events sent since we generally
                             // only care about the times that we had to actually retrieve and process rows
@@ -375,12 +375,12 @@ private async Task GetTableChangesAsync(SqlConnection connection, CancellationTo
                     throw;
                 }
             }
-            this._logger.LogDebugWithThreadId("END GetTableChanges");
+            this._logger.LogDebug("END GetTableChanges");
         }
 
         private async Task ProcessTableChangesAsync()
         {
-            this._logger.LogDebugWithThreadId("BEGIN ProcessTableChanges");
+            this._logger.LogDebug("BEGIN ProcessTableChanges");
             if (this._rowsToProcess.Count > 0)
             {
                 IReadOnlyList<SqlChange<T>> changes = null;
@@ -407,7 +407,7 @@ private async Task ProcessTableChangesAsync()
                 {
                     var input = new TriggeredFunctionData() { TriggerValue = changes };
 
-                    this._logger.LogDebugWithThreadId("Executing triggered function");
+                    this._logger.LogDebug("Executing triggered function");
                     var stopwatch = Stopwatch.StartNew();
 
                     FunctionResult result = await this._executor.TryExecuteAsync(input, this._cancellationTokenSourceExecutor.Token);
@@ -419,7 +419,7 @@ private async Task ProcessTableChangesAsync()
                     };
                     if (result.Succeeded)
                     {
-                        this._logger.LogDebugWithThreadId($"Successfully triggered function. Duration={durationMs}ms");
+                        this._logger.LogDebug($"Successfully triggered function. Duration={durationMs}ms");
                         TelemetryInstance.TrackEvent(TelemetryEventName.TriggerFunction, this._telemetryProps, measures);
                         // We've successfully fully processed these so set them to be released in the cleanup phase
                         this._rowsToRelease = this._rowsToProcess;
@@ -441,7 +441,7 @@ private async Task ProcessTableChangesAsync()
                 // any we still ensure everything is reset to a clean state
                 await this.ClearRowsAsync();
             }
-            this._logger.LogDebugWithThreadId("END ProcessTableChanges");
+            this._logger.LogDebug("END ProcessTableChanges");
         }
 
         /// <summary>
@@ -458,9 +458,9 @@ private async void RunLeaseRenewalLoopAsync()
 
                 using (var connection = new SqlConnection(this._connectionString))
                 {
-                    this._logger.LogDebugWithThreadId("BEGIN OpenLeaseRenewalLoopConnection");
+                    this._logger.LogDebug("BEGIN OpenLeaseRenewalLoopConnection");
                     await connection.OpenAsync(token);
-                    this._logger.LogDebugWithThreadId("END OpenLeaseRenewalLoopConnection");
+                    this._logger.LogDebug("END OpenLeaseRenewalLoopConnection");
 
                     bool forceReconnect = false;
                     while (!token.IsCancellationRequested)
@@ -509,9 +509,9 @@ private async void RunLeaseRenewalLoopAsync()
 
         private async Task RenewLeasesAsync(SqlConnection connection, CancellationToken token)
         {
-            this._logger.LogDebugWithThreadId("BEGIN WaitRowsLock - RenewLeases");
+            this._logger.LogDebug("BEGIN WaitRowsLock - RenewLeases");
             await this._rowsLock.WaitAsync(token);
-            this._logger.LogDebugWithThreadId("END WaitRowsLock - RenewLeases");
+            this._logger.LogDebug("END WaitRowsLock - RenewLeases");
 
             if (this._state == State.ProcessingChanges && this._rowsToProcess.Count > 0)
             {
@@ -522,13 +522,13 @@ private async Task RenewLeasesAsync(SqlConnection connection, CancellationToken
                     {
                         using (SqlCommand renewLeasesCommand = this.BuildRenewLeasesCommand(connection, transaction))
                         {
-                            this._logger.LogDebugWithThreadId($"BEGIN RenewLeases Query={renewLeasesCommand.CommandText}");
+                            this._logger.LogDebug($"BEGIN RenewLeases Query={renewLeasesCommand.CommandText}");
                             var stopwatch = Stopwatch.StartNew();
 
                             int rowsAffected = await renewLeasesCommand.ExecuteNonQueryAsync(token);
 
                             long durationMs = stopwatch.ElapsedMilliseconds;
-                            this._logger.LogDebugWithThreadId($"END RenewLeases Duration={durationMs}ms RowsAffected={rowsAffected}");
+                            this._logger.LogDebug($"END RenewLeases Duration={durationMs}ms RowsAffected={rowsAffected}");
 
                             if (rowsAffected > 0)
                             {
@@ -588,7 +588,7 @@ private async Task RenewLeasesAsync(SqlConnection connection, CancellationToken
             }
 
             // Want to always release the lock at the end, even if renewing the leases failed.
-            this._logger.LogDebugWithThreadId("ReleaseRowsLock - RenewLeases");
+            this._logger.LogDebug("ReleaseRowsLock - RenewLeases");
             this._rowsLock.Release();
         }
 
@@ -597,15 +597,15 @@ private async Task RenewLeasesAsync(SqlConnection connection, CancellationToken
         /// </summary>
         private async Task ClearRowsAsync()
         {
-            this._logger.LogDebugWithThreadId("BEGIN WaitRowsLock - ClearRows");
+            this._logger.LogDebug("BEGIN WaitRowsLock - ClearRows");
             await this._rowsLock.WaitAsync();
-            this._logger.LogDebugWithThreadId("END WaitRowsLock - ClearRows");
+            this._logger.LogDebug("END WaitRowsLock - ClearRows");
 
             this._leaseRenewalCount = 0;
             this._state = State.CheckingForChanges;
             this._rowsToProcess = new List<IReadOnlyDictionary<string, object>>();
 
-            this._logger.LogDebugWithThreadId("ReleaseRowsLock - ClearRows");
+            this._logger.LogDebug("ReleaseRowsLock - ClearRows");
             this._rowsLock.Release();
         }
 
@@ -632,22 +632,22 @@ private async Task ReleaseLeasesAsync(SqlConnection connection, CancellationToke
                             // Release the leases held on "_rowsToRelease".
                             using (SqlCommand releaseLeasesCommand = this.BuildReleaseLeasesCommand(connection, transaction))
                             {
-                                this._logger.LogDebugWithThreadId($"BEGIN ReleaseLeases Query={releaseLeasesCommand.CommandText}");
+                                this._logger.LogDebug($"BEGIN ReleaseLeases Query={releaseLeasesCommand.CommandText}");
                                 var commandSw = Stopwatch.StartNew();
                                 int rowsUpdated = await releaseLeasesCommand.ExecuteNonQueryAsync(token);
                                 releaseLeasesDurationMs = commandSw.ElapsedMilliseconds;
-                                this._logger.LogDebugWithThreadId($"END ReleaseLeases Duration={releaseLeasesDurationMs}ms RowsUpdated={rowsUpdated}");
+                                this._logger.LogDebug($"END ReleaseLeases Duration={releaseLeasesDurationMs}ms RowsUpdated={rowsUpdated}");
                             }
 
                             // Update the global state table if we have processed all changes with ChangeVersion <= newLastSyncVersion,
                             // and clean up the leases table to remove all rows with ChangeVersion <= newLastSyncVersion.
                             using (SqlCommand updateTablesPostInvocationCommand = this.BuildUpdateTablesPostInvocation(connection, transaction, newLastSyncVersion))
                             {
-                                this._logger.LogDebugWithThreadId($"BEGIN UpdateTablesPostInvocation Query={updateTablesPostInvocationCommand.CommandText}");
+                                this._logger.LogDebug($"BEGIN UpdateTablesPostInvocation Query={updateTablesPostInvocationCommand.CommandText}");
                                 var commandSw = Stopwatch.StartNew();
                                 await updateTablesPostInvocationCommand.ExecuteNonQueryAsync(token);
                                 updateLastSyncVersionDurationMs = commandSw.ElapsedMilliseconds;
-                                this._logger.LogDebugWithThreadId($"END UpdateTablesPostInvocation Duration={updateLastSyncVersionDurationMs}ms");
+                                this._logger.LogDebug($"END UpdateTablesPostInvocation Duration={updateLastSyncVersionDurationMs}ms");
                             }
                             transaction.Commit();
 
@@ -718,7 +718,7 @@ private long RecomputeLastSyncVersion()
             // Also this LastSyncVersion is actually updated in the GlobalState table only after verifying that the changes with
             // changeVersion <= newLastSyncVersion have been processed in BuildUpdateTablesPostInvocation query.
             long lastSyncVersion = changeVersionSet.ElementAt(changeVersionSet.Count > 1 ? changeVersionSet.Count - 2 : 0);
-            this._logger.LogDebugWithThreadId($"RecomputeLastSyncVersion. LastSyncVersion={lastSyncVersion} ChangeVersionSet={string.Join(",", changeVersionSet)}");
+            this._logger.LogDebug($"RecomputeLastSyncVersion. LastSyncVersion={lastSyncVersion} ChangeVersionSet={string.Join(",", changeVersionSet)}");
             return lastSyncVersion;
         }
 
@@ -730,7 +730,7 @@ private long RecomputeLastSyncVersion()
         /// <returns>The list of changes</returns>
         private IReadOnlyList<SqlChange<T>> ProcessChanges()
         {
-            this._logger.LogDebugWithThreadId("BEGIN ProcessChanges");
+            this._logger.LogDebug("BEGIN ProcessChanges");
             var changes = new List<SqlChange<T>>();
             foreach (IReadOnlyDictionary<string, object> row in this._rowsToProcess)
             {
@@ -744,7 +744,7 @@ private IReadOnlyList<SqlChange<T>> ProcessChanges()
 
                 changes.Add(new SqlChange<T>(operation, Utils.JsonDeserializeObject<T>(Utils.JsonSerializeObject(item))));
             }
-            this._logger.LogDebugWithThreadId("END ProcessChanges");
+            this._logger.LogDebug("END ProcessChanges");
             return changes;
         }