Additional logs added (#3710)

* Additional logs added

* Fixed printing Object

src/Microsoft.Health.Fhir.Core/Features/Operations/Reindex/ReindexJobTask.cs

@@ -139,6 +139,7 @@ public async Task ExecuteAsync(ReindexJobRecord reindexJobRecord, WeakETag weakE
                 // If no queries have been added to the progress then this is a new job
                 if (_reindexJobRecord.QueryList?.Count == 0)
                 {
+                    _logger.LogInformation("Picked up a new job");
                     if (!await TryPopulateNewJobFields(cancellationToken))
                     {
                         return;
@@ -375,6 +376,7 @@ private async Task ProcessJob()
                         // if this query has a created task, cancel it
                         if (queryCancellationTokens.TryGetValue(staleQuery, out var tokenSource))
                         {
+                            _logger.LogInformation("Stale Query that is being reset to queued. Status : {StaleQueryStatus}, StartResourceSurrogateId : {StaleQueryStartSurrogateId}, ResourceType : {StaleQueryResourceType}", staleQuery.Status, staleQuery.StartResourceSurrogateId, staleQuery.ResourceType);
                             try
                             {
                                 tokenSource.Cancel(false);
@@ -409,6 +411,7 @@ private async Task ProcessJob()
                     var finishedTasks = queryTasks.Where(t => t.IsCompleted).ToArray();
                     foreach (var finishedTask in finishedTasks)
                     {
+                        _logger.LogInformation("Details of Reindex Task completed LastModified : {LastModified} ResourceType: {ResourceType} StartResourceSurrogateId: {StartResourceSurrogateId}", finishedTask.Result.LastModified, finishedTask.Result.ResourceType, finishedTask.Result.StartResourceSurrogateId);
                         queryTasks.Remove(finishedTask);
                         queryCancellationTokens.Remove(await finishedTask);
                     }
@@ -428,9 +431,10 @@ private async Task ProcessJob()
                         _reindexJobRecord.Status = wrapper.JobRecord.Status;
                     }
                 }
-                catch (Exception)
+                catch (Exception ex)
                 {
                     // if something went wrong with fetching job status, we shouldn't fail process loop.
+                    _logger.LogWarning(ex, "Reindex error occurred while fetching job status.");
                 }
                 finally
                 {
@@ -543,6 +547,7 @@ private async Task<ReindexJobQueryStatus> ProcessQueryAsync(ReindexJobQueryStatu
                         if (_reindexJobRecord.QueryList.Count > 10)
                         {
                             var queryStatusToRemove = _reindexJobRecord.QueryList.Keys.Where(q => q.Status == OperationStatus.Completed).OrderBy(q => q.LastModified).FirstOrDefault();
+                            _logger.LogInformation("Reindex job that is being removed from  query list StartResourceSurrogateId: {StartResourceSurrogateId}, ResourceType: {ResourceType}, FailureCount: {FailureCount}, Status: {Status}", queryStatusToRemove?.StartResourceSurrogateId, queryStatusToRemove?.ResourceType, queryStatusToRemove?.FailureCount, queryStatusToRemove?.Status);
                             _reindexJobRecord.QueryList.TryRemove(queryStatusToRemove, out var removedByte);
                         }
 

src/Microsoft.Health.Fhir.Core/Features/Operations/Reindex/ReindexJobWorker.cs

@@ -78,29 +78,34 @@ public async Task ExecuteAsync(CancellationToken cancellationToken)
                     // Check for any new Reindex Jobs
                     try
                     {
-                        // Remove all completed tasks.
+                        _logger.LogInformation("Number of Tasks in the list {RunningTasksCount}.", runningTasks.Count);
+
                         // Remove all completed tasks.
                         foreach (var task in runningTasks.Where(task => task.Task.IsCompleted).ToList())
                         {
                             task.Scope.Dispose();
                             runningTasks.Remove(task);
                         }
 
+                        _logger.LogInformation("Number of running Tasks after removing completed tasks {RunningTasksCount}.", runningTasks.Count);
+
                         // Get list of available jobs.
                         if (runningTasks.Count < _reindexJobConfiguration.MaximumNumberOfConcurrentJobsAllowed)
                         {
                             using IScoped<IFhirOperationDataStore> store = _fhirOperationDataStoreFactory.Invoke();
 
-                            _logger.LogTrace("Querying datastore for reindex jobs.");
+                            _logger.LogInformation("Querying datastore for reindex jobs.");
 
                             IReadOnlyCollection<ReindexJobWrapper> jobs = await store.Value.AcquireReindexJobsAsync(
                                 _reindexJobConfiguration.MaximumNumberOfConcurrentJobsAllowed,
                                 _reindexJobConfiguration.JobHeartbeatTimeoutThreshold,
                                 cancellationToken);
 
+                            _logger.LogInformation("No.of reindex jobs picked.{JobsPicked} ", jobs.Count);
+
                             foreach (ReindexJobWrapper job in jobs)
                             {
-                                _logger.LogTrace("Picked up reindex job: {JobId}.", job.JobRecord.Id);
+                                _logger.LogInformation("Picked up reindex job: {JobId}.", job.JobRecord.Id);
 
                                 IScoped<IReindexJobTask> reindexJobScope = _reindexJobTaskFactory.Invoke();
                                 runningTasks.Add(
@@ -112,6 +117,7 @@ public async Task ExecuteAsync(CancellationToken cancellationToken)
                     catch (OperationCanceledException) when (cancellationToken.IsCancellationRequested)
                     {
                         // End the execution of the task
+                        _logger.LogDebug("Polling Reindex jobs canceled.");
                     }
                     catch (Exception ex)
                     {
@@ -127,6 +133,7 @@ public async Task ExecuteAsync(CancellationToken cancellationToken)
                 catch (OperationCanceledException) when (cancellationToken.IsCancellationRequested)
                 {
                     // End the execution of the task
+                    _logger.LogDebug("Reindex job worker canceled.");
                 }
             }
         }

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

@@ -16,6 +16,7 @@
 using System.Threading;
 using System.Threading.Tasks;
 using EnsureThat;
+using Hl7.Fhir.Rest;
 using Microsoft.Data.SqlClient;
 using Microsoft.Extensions.Logging;
 using Microsoft.Extensions.Options;
@@ -920,6 +921,7 @@ protected async override Task<SearchResult> SearchForReindexInternalAsync(Search
                 results = new SearchResult(0, new List<Tuple<string, string>>());
             }
 
+            _logger.LogInformation("For Reindex, Resource Type={ResourceType} Count={Count} MaxResourceSurrogateId={MaxResourceSurrogateId}", resourceType, results.TotalCount, results.MaxResourceSurrogateId);
             return results;
         }