[Http Operations] [Logs] Preconditional failures logs (#3598)

* Clean config file.

Bundle orchestrator improvements.

* Logging to conditional updates

* Adding more logs to conditional operations

* Undo fix in bundle to isolate the PR changes

* Adding validations to arguments

* Improvements in logging. Adding new component to track statistics.

* Improvements in logs

src/Microsoft.Health.Fhir.Core.UnitTests/Logging/LongRunningOperationStatisticsTests.cs

@@ -0,0 +1,43 @@
+// -------------------------------------------------------------------------------------------------
+// Copyright (c) Microsoft Corporation. All rights reserved.
+// Licensed under the MIT License (MIT). See LICENSE in the repo root for license information.
+// -------------------------------------------------------------------------------------------------
+
+using System.Threading;
+using Microsoft.Health.Fhir.Core.Logging;
+using Microsoft.Health.Fhir.Tests.Common;
+using Microsoft.Health.Test.Utilities;
+using Xunit;
+
+namespace Microsoft.Health.Fhir.Core.UnitTests.Logging
+{
+    [Trait(Traits.OwningTeam, OwningTeam.Fhir)]
+    [Trait(Traits.Category, Categories.Operations)]
+    public class LongRunningOperationStatisticsTests
+    {
+        [Fact]
+        public void GivenALongRunningOperation_WhenUsingStatistics_ThenComputeOperationsAsExpected()
+        {
+            const int count = 10;
+            const int sleeptime = 10;
+
+            LongRunningOperationStatistics statistics = new LongRunningOperationStatistics("operation");
+
+            statistics.StartCollectingResults();
+
+            for (int i = 0; i < count; i++)
+            {
+                statistics.Iterate();
+                Thread.Sleep(sleeptime);
+            }
+
+            statistics.StopCollectingResults();
+            string json = statistics.GetStatisticsAsJson();
+
+            Assert.Equal(count, statistics.IterationCount);
+            Assert.True(statistics.ElapsedMilliseconds > 0, "Elapsed Milliseconds is not greater than ZERO.");
+            Assert.True(statistics.ElapsedMilliseconds >= (count * sleeptime), "Elapsed Milliseconds is not than the expected time.");
+            Assert.Contains(statistics.GetLoggingCategory(), json);
+        }
+    }
+}

src/Microsoft.Health.Fhir.Core/Extensions/SearchServiceExtensions.cs

@@ -10,10 +10,11 @@
 using System.Linq;
 using System.Threading;
 using System.Threading.Tasks;
-using DotLiquid.Tags;
+using Microsoft.Extensions.Logging;
 using Microsoft.Health.Fhir.Core.Exceptions;
 using Microsoft.Health.Fhir.Core.Features;
 using Microsoft.Health.Fhir.Core.Features.Search;
+using Microsoft.Health.Fhir.Core.Logging;
 
 namespace Microsoft.Health.Fhir.Core.Extensions
 {
@@ -48,7 +49,8 @@ public static class SearchServiceExtensions
             IReadOnlyList<Tuple<string, string>> conditionalParameters,
             CancellationToken cancellationToken,
             int? count = 2, // Most "Conditional" logic needs only 0, 1 or >1, so here we can limit to "2"
-            string continuationToken = null)
+            string continuationToken = null,
+            Microsoft.Extensions.Logging.ILogger logger = null)
         {
             // Filters search parameters that can limit the number of results (e.g. _count=1)
             IList<Tuple<string, string>> filteredParameters = conditionalParameters
@@ -64,34 +66,57 @@ public static class SearchServiceExtensions
 
             var matchedResults = new List<SearchResultEntry>();
             string lastContinuationToken = continuationToken;
-
-            do
+            LongRunningOperationStatistics statistics = new LongRunningOperationStatistics(operationName: "conditionalSearchAsync");
+            try
             {
-                var searchParameters = new List<Tuple<string, string>>(filteredParameters);
-                if (!string.IsNullOrEmpty(lastContinuationToken))
+                statistics.StartCollectingResults();
+                do
                 {
-                    searchParameters.Add(Tuple.Create(KnownQueryParameterNames.ContinuationToken, ContinuationTokenConverter.Encode(lastContinuationToken)));
-                }
+                    var searchParameters = new List<Tuple<string, string>>(filteredParameters);
+                    if (!string.IsNullOrEmpty(lastContinuationToken))
+                    {
+                        searchParameters.Add(Tuple.Create(KnownQueryParameterNames.ContinuationToken, ContinuationTokenConverter.Encode(lastContinuationToken)));
+                    }
 
-                SearchResult results = await searchService.SearchAsync(instanceType, searchParameters.ToImmutableList(), cancellationToken);
-                lastContinuationToken = results?.ContinuationToken;
+                    statistics.Iterate();
 
-                // Check if all parameters passed in were unused, this would result in no search parameters being applied to search results
-                int? totalUnusedParameters = results?.UnsupportedSearchParameters.Count;
-                if (totalUnusedParameters == userProvidedParameterCount)
-                {
-                    throw new PreconditionFailedException(string.Format(CultureInfo.InvariantCulture, Core.Resources.ConditionalOperationNotSelectiveEnough, instanceType));
+                    SearchResult results = await searchService.SearchAsync(instanceType, searchParameters.ToImmutableList(), cancellationToken);
+                    lastContinuationToken = results?.ContinuationToken;
+
+                    // Check if all parameters passed in were unused, this would result in no search parameters being applied to search results
+                    int? totalUnusedParameters = results?.UnsupportedSearchParameters.Count;
+                    if (totalUnusedParameters == userProvidedParameterCount)
+                    {
+                        logger?.LogInformation("PreconditionFailed: ConditionalOperationNotSelectiveEnough");
+                        throw new PreconditionFailedException(string.Format(CultureInfo.InvariantCulture, Core.Resources.ConditionalOperationNotSelectiveEnough, instanceType));
+                    }
+
+                    if (results?.Results.Any() == true)
+                    {
+                        matchedResults.AddRange(
+                            results?.Results
+                                .Where(x => x.SearchEntryMode == ValueSets.SearchEntryMode.Match)
+                                .Take(Math.Max(count.HasValue ? 0 : results.Results.Count(), count.GetValueOrDefault() - matchedResults.Count)));
+                    }
                 }
+                while (count.HasValue && matchedResults.Count < count && !string.IsNullOrEmpty(lastContinuationToken));
+            }
+            finally
+            {
+                statistics.StopCollectingResults();
 
-                if (results?.Results.Any() == true)
+                if (statistics.IterationCount > 1 && logger != null)
                 {
-                    matchedResults.AddRange(
-                        results?.Results
-                            .Where(x => x.SearchEntryMode == ValueSets.SearchEntryMode.Match)
-                            .Take(Math.Max(count.HasValue ? 0 : results.Results.Count(), count.GetValueOrDefault() - matchedResults.Count)));
+                    try
+                    {
+                        logger.LogInformation(statistics.GetStatisticsAsJson());
+                    }
+                    catch (Exception ex)
+                    {
+                        logger.LogWarning(ex, "Error computing operation statistics. This error will not block the operation processing.");
+                    }
                 }
             }
-            while (count.HasValue && matchedResults.Count < count && !string.IsNullOrEmpty(lastContinuationToken));
 
             return (matchedResults, lastContinuationToken);
         }

src/Microsoft.Health.Fhir.Core/Features/Operations/BulkDelete/Handlers/CreateBulkDeleteHandler.cs

@@ -65,7 +65,7 @@ public async Task<CreateBulkDeleteResponse> Handle(CreateBulkDeleteRequest reque
             searchParameters.Add(Tuple.Create("_lastUpdated", $"lt{dateCurrent}"));
 
             // Should not run bulk delete if any of the search parameters are invalid as it can lead to unpredicatable results
-            await _searchService.ConditionalSearchAsync(request.ResourceType, searchParameters, cancellationToken, 1);
+            await _searchService.ConditionalSearchAsync(request.ResourceType, searchParameters, cancellationToken, count: 1);
             if (_contextAccessor.RequestContext?.BundleIssues?.Count > 0)
             {
                 throw new BadRequestException(_contextAccessor.RequestContext.BundleIssues.Select(issue => issue.Diagnostics).ToList());

src/Microsoft.Health.Fhir.Core/Logging/BaseOperationStatistics.cs

@@ -0,0 +1,38 @@
+// -------------------------------------------------------------------------------------------------
+// Copyright (c) Microsoft Corporation. All rights reserved.
+// Licensed under the MIT License (MIT). See LICENSE in the repo root for license information.
+// -------------------------------------------------------------------------------------------------
+
+using System.Diagnostics;
+
+namespace Microsoft.Health.Fhir.Core.Logging
+{
+    public abstract class BaseOperationStatistics
+    {
+        private readonly Stopwatch _stopwatch;
+
+        protected BaseOperationStatistics()
+        {
+            _stopwatch = new Stopwatch();
+        }
+
+        public long ElapsedMilliseconds
+        {
+            get { return _stopwatch.ElapsedMilliseconds; }
+        }
+
+        public abstract string GetStatisticsAsJson();
+
+        public abstract string GetLoggingCategory();
+
+        public virtual void StartCollectingResults()
+        {
+            _stopwatch.Start();
+        }
+
+        public virtual void StopCollectingResults()
+        {
+            _stopwatch.Stop();
+        }
+    }
+}

src/Microsoft.Health.Fhir.Core/Logging/LongRunningOperationStatistics.cs

@@ -0,0 +1,55 @@
+// -------------------------------------------------------------------------------------------------
+// Copyright (c) Microsoft Corporation. All rights reserved.
+// Licensed under the MIT License (MIT). See LICENSE in the repo root for license information.
+// -------------------------------------------------------------------------------------------------
+
+using System;
+using System.Threading;
+using EnsureThat;
+using Newtonsoft.Json.Linq;
+
+namespace Microsoft.Health.Fhir.Core.Logging
+{
+    public sealed class LongRunningOperationStatistics : BaseOperationStatistics
+    {
+        private readonly string _operationName;
+
+        private int _iterationCount;
+
+        public LongRunningOperationStatistics(string operationName)
+            : base()
+        {
+            EnsureArg.IsNotNull(operationName, nameof(operationName));
+
+            _operationName = operationName;
+            _iterationCount = 0;
+        }
+
+        public int IterationCount
+        {
+            get
+            {
+                return _iterationCount;
+            }
+        }
+
+        public void Iterate()
+        {
+            Interlocked.Increment(ref _iterationCount);
+        }
+
+        public override string GetLoggingCategory() => _operationName;
+
+        public override string GetStatisticsAsJson()
+        {
+            JObject serializableEntity = JObject.FromObject(new
+            {
+                label = GetLoggingCategory(),
+                iterationCount = _iterationCount,
+                executionTime = ElapsedMilliseconds,
+            });
+
+            return serializableEntity.ToString();
+        }
+    }
+}

src/Microsoft.Health.Fhir.CosmosDb/Features/Storage/CosmosFhirDataStore.cs

@@ -307,9 +307,11 @@ await retryPolicy.ExecuteAsync(
                 // The backwards compatibility behavior of Stu3 is to return 412 Precondition Failed instead of a 400 Client Error
                 if (_modelInfoProvider.Version == FhirSpecification.Stu3)
                 {
+                    _logger.LogInformation("PreconditionFailed: IfMatchHeaderRequiredForResource");
                     throw new PreconditionFailedException(string.Format(Core.Resources.IfMatchHeaderRequiredForResource, resource.ResourceTypeName));
                 }
 
+                _logger.LogInformation("BadRequest: IfMatchHeaderRequiredForResource");
                 throw new BadRequestException(string.Format(Core.Resources.IfMatchHeaderRequiredForResource, resource.ResourceTypeName));
             }
 
@@ -334,11 +336,13 @@ await retryPolicy.ExecuteAsync(
 
                     if (weakETag != null)
                     {
+                        _logger.LogInformation("ResourceNotFound: ResourceNotFoundByIdAndVersion");
                         throw new ResourceNotFoundException(string.Format(Core.Resources.ResourceNotFoundByIdAndVersion, resource.ResourceTypeName, resource.ResourceId, weakETag.VersionId));
                     }
 
                     if (!allowCreate)
                     {
+                        _logger.LogInformation("MethodNotAllowed: ResourceCreationNotAllowed");
                         throw new MethodNotAllowedException(Core.Resources.ResourceCreationNotAllowed);
                     }
 
@@ -350,9 +354,11 @@ await retryPolicy.ExecuteAsync(
                     // The backwards compatibility behavior of Stu3 is to return 409 Conflict instead of a 412 Precondition Failed
                     if (_modelInfoProvider.Version == FhirSpecification.Stu3)
                     {
+                        _logger.LogInformation("ResourceConflict: ResourceVersionConflict");
                         throw new ResourceConflictException(weakETag);
                     }
 
+                    _logger.LogInformation("PreconditionFailed: ResourceVersionConflict");
                     throw new PreconditionFailedException(string.Format(Core.Resources.ResourceVersionConflict, weakETag.VersionId));
                 }
 

src/Microsoft.Health.Fhir.Shared.Api.UnitTests/Features/Resources/Bundle/BundleHandlerTests.cs

@@ -81,17 +81,18 @@ public BundleHandlerTests()
 
             ISearchService searchService = Substitute.For<ISearchService>();
             var resourceReferenceResolver = new ResourceReferenceResolver(searchService, new QueryStringParser());
-            var transactionBundleValidator = new TransactionBundleValidator(resourceReferenceResolver);
+
+            var transactionBundleValidatorLogger = Substitute.For<ILogger<TransactionBundleValidator>>();
+            var transactionBundleValidator = new TransactionBundleValidator(resourceReferenceResolver, transactionBundleValidatorLogger);
 
             var bundleHttpContextAccessor = new BundleHttpContextAccessor();
 
             _bundleConfiguration = new BundleConfiguration();
             var bundleOptions = Substitute.For<IOptions<BundleConfiguration>>();
             bundleOptions.Value.Returns(_bundleConfiguration);
 
-            var logger = Substitute.For<ILogger<BundleOrchestrator>>();
-
-            var bundleOrchestrator = new BundleOrchestrator(bundleOptions, logger);
+            var bundleOrchestratorLogger = Substitute.For<ILogger<BundleOrchestrator>>();
+            var bundleOrchestrator = new BundleOrchestrator(bundleOptions, bundleOrchestratorLogger);
 
             IFeatureCollection featureCollection = CreateFeatureCollection();
             var httpContext = new DefaultHttpContext(featureCollection)

src/Microsoft.Health.Fhir.Shared.Api.UnitTests/Features/Resources/Bundle/TransactionBundleValidatorTests.cs

@@ -7,6 +7,8 @@
 using System.Collections.Generic;
 using System.Linq;
 using System.Threading;
+using Castle.Core.Logging;
+using Microsoft.Extensions.Logging;
 using Microsoft.Health.Fhir.Api.Features.Resources.Bundle;
 using Microsoft.Health.Fhir.Api.Features.Routing;
 using Microsoft.Health.Fhir.Core.Exceptions;
@@ -28,12 +30,13 @@ namespace Microsoft.Health.Fhir.Api.UnitTests.Features.Resources.Bundle
     public class TransactionBundleValidatorTests
     {
         private readonly ISearchService _searchService = Substitute.For<ISearchService>();
+        private readonly ILogger<TransactionBundleValidator> _logger = Substitute.For<ILogger<TransactionBundleValidator>>();
         private readonly TransactionBundleValidator _transactionBundleValidator;
         private readonly Dictionary<string, (string resourceId, string resourceType)> _idDictionary;
 
         public TransactionBundleValidatorTests()
         {
-            _transactionBundleValidator = new TransactionBundleValidator(new ResourceReferenceResolver(_searchService, new QueryStringParser()));
+            _transactionBundleValidator = new TransactionBundleValidator(new ResourceReferenceResolver(_searchService, new QueryStringParser()), _logger);
             _idDictionary = new Dictionary<string, (string resourceId, string resourceType)>();
         }
 

src/Microsoft.Health.Fhir.Shared.Api/Features/Resources/Bundle/BundleHandlerStatistics.cs

@@ -9,27 +9,25 @@
 using System.Linq;
 using System.Net;
 using Hl7.Fhir.Utility;
+using Microsoft.Health.Fhir.Core.Logging;
 using Newtonsoft.Json.Linq;
 using static Hl7.Fhir.Model.Bundle;
 
 namespace Microsoft.Health.Fhir.Api.Features.Resources.Bundle
 {
-    internal sealed class BundleHandlerStatistics
+    internal sealed class BundleHandlerStatistics : BaseOperationStatistics
     {
-        private const string LoggingLabel = "bundleStatistics";
-
-        private readonly Stopwatch _stopwatch;
+        private const string LoggingCategory = "bundleStatistics";
 
         private readonly List<BundleHandlerStatisticEntry> _entries;
 
         public BundleHandlerStatistics(BundleType? bundleType, BundleProcessingLogic processingLogic, int numberOfResources)
+            : base()
         {
             BundleType = bundleType;
             ProcessingLogic = processingLogic;
             NumberOfResources = numberOfResources;
             _entries = new List<BundleHandlerStatisticEntry>();
-
-            _stopwatch = new Stopwatch();
         }
 
         public int NumberOfResources { get; }
@@ -38,17 +36,9 @@ public BundleHandlerStatistics(BundleType? bundleType, BundleProcessingLogic pro
 
         public BundleProcessingLogic ProcessingLogic { get; }
 
-        public void StartCollectingResults()
-        {
-            _stopwatch.Start();
-        }
-
-        public void StopCollectingResults()
-        {
-            _stopwatch.Stop();
-        }
+        public override string GetLoggingCategory() => LoggingCategory;
 
-        public string GetStatisticsAsJson()
+        public override string GetStatisticsAsJson()
         {
             var finalStatistics = _entries
                 .GroupBy(e => string.Concat(e.HttpVerb, " - ", e.HttpStatusCode))
@@ -61,11 +51,11 @@ public string GetStatisticsAsJson()
 
             JObject serializableEntity = JObject.FromObject(new
             {
-                label = LoggingLabel,
+                label = GetLoggingCategory(),
                 bundleType = BundleType.ToString(),
                 processingLogic = ProcessingLogic.ToString(),
                 numberOfResources = NumberOfResources,
-                executionTime = _stopwatch.ElapsedMilliseconds,
+                executionTime = ElapsedMilliseconds,
                 success = successedRequests,
                 errors = failedRequests,
                 customerErrors = customerFailedRequests,