Adding better logging to BadRequestExceptions (#3856)

src/Microsoft.Health.Fhir.Core/Features/Search/SearchService.cs

@@ -11,6 +11,7 @@ using System.Threading;
 using System.Threading.Tasks;
 using EnsureThat;
 using Hl7.Fhir.Rest;
+using Microsoft.Extensions.Logging;
 using Microsoft.Health.Core;
 using Microsoft.Health.Fhir.Core.Exceptions;
 using Microsoft.Health.Fhir.Core.Extensions;
@@ -26,19 +27,23 @@ namespace Microsoft.Health.Fhir.Core.Features.Search
     {
         private readonly ISearchOptionsFactory _searchOptionsFactory;
         private readonly IFhirDataStore _fhirDataStore;
+        private readonly ILogger _logger;
 
         /// <summary>
         /// Initializes a new instance of the <see cref="SearchService"/> class.
         /// </summary>
         /// <param name="searchOptionsFactory">The search options factory.</param>
         /// <param name="fhirDataStore">The data store</param>
-        protected SearchService(ISearchOptionsFactory searchOptionsFactory, IFhirDataStore fhirDataStore)
+        /// <param name="logger">Logger</param>
+        protected SearchService(ISearchOptionsFactory searchOptionsFactory, IFhirDataStore fhirDataStore, ILogger logger)
         {
             EnsureArg.IsNotNull(searchOptionsFactory, nameof(searchOptionsFactory));
             EnsureArg.IsNotNull(fhirDataStore, nameof(fhirDataStore));
+            EnsureArg.IsNotNull(logger, nameof(logger));
 
             _searchOptionsFactory = searchOptionsFactory;
             _fhirDataStore = fhirDataStore;
+            _logger = logger;
         }
 
         /// <inheritdoc />
@@ -92,6 +97,7 @@ namespace Microsoft.Health.Fhir.Core.Features.Search
                 if (since != null)
                 {
                     // _at and _since cannot be both specified.
+                    _logger.LogWarning("Invalid Search Operation (_since)");
                     throw new InvalidSearchOperationException(
                         string.Format(
                             CultureInfo.InvariantCulture,
@@ -102,7 +108,8 @@ namespace Microsoft.Health.Fhir.Core.Features.Search
 
                 if (before != null)
                 {
-                    // _at and _since cannot be both specified.
+                    // _at and _before cannot be both specified.
+                    _logger.LogWarning("Invalid Search Operation (_before)");
                     throw new InvalidSearchOperationException(
                         string.Format(
                             CultureInfo.InvariantCulture,
@@ -119,6 +126,7 @@ namespace Microsoft.Health.Fhir.Core.Features.Search
                 if (beforeOffset.CompareTo(Clock.UtcNow) > 0)
                 {
                     // you cannot specify a value for _before in the future
+                    _logger.LogWarning("Invalid Search Operation (_before in the future)");
                     throw new InvalidSearchOperationException(
                         string.Format(
                             CultureInfo.InvariantCulture,
@@ -169,6 +177,7 @@ namespace Microsoft.Health.Fhir.Core.Features.Search
             {
                 if (!string.Equals(sort.TrimStart('-'), KnownQueryParameterNames.LastUpdated, StringComparison.Ordinal))
                 {
+                    _logger.LogWarning("Invalid Search Operation (SearchSortParameterNotSupported)");
                     throw new InvalidSearchOperationException(
                         string.Format(
                             CultureInfo.InvariantCulture,
@@ -198,6 +207,7 @@ namespace Microsoft.Health.Fhir.Core.Features.Search
 
                 if (resource == null)
                 {
+                    _logger.LogWarning("Resource Not Found (ResourceNotFoundById)");
                     throw new ResourceNotFoundException(string.Format(Core.Resources.ResourceNotFoundById, resourceType, resourceId));
                 }
             }

src/Microsoft.Health.Fhir.CosmosDb/Features/Search/FhirCosmosSearchService.cs

@@ -55,7 +55,7 @@ namespace Microsoft.Health.Fhir.CosmosDb.Features.Search
             CompartmentSearchRewriter compartmentSearchRewriter,
             SmartCompartmentSearchRewriter smartCompartmentSearchRewriter,
             ILogger<FhirCosmosSearchService> logger)
-            : base(searchOptionsFactory, fhirDataStore)
+            : base(searchOptionsFactory, fhirDataStore, logger)
         {
             EnsureArg.IsNotNull(fhirDataStore, nameof(fhirDataStore));
             EnsureArg.IsNotNull(queryBuilder, nameof(queryBuilder));
@@ -129,6 +129,7 @@ namespace Microsoft.Health.Fhir.CosmosDb.Features.Search
                 if (includeExpressions.Any(e => e.Iterate) || revIncludeExpressions.Any(e => e.Iterate))
                 {
                     // We haven't implemented this yet.
+                    _logger.LogWarning("Bad Request (IncludeIterateNotSupported)");
                     throw new BadRequestException(Resources.IncludeIterateNotSupported);
                 }
             }
@@ -294,11 +295,13 @@ namespace Microsoft.Health.Fhir.CosmosDb.Features.Search
                     chainedOptions,
                     queryTimeout.Token))
                 {
+                    _logger.LogWarning("Invalid Search Operation (ChainedExpressionSubqueryLimit)");
                     throw new InvalidSearchOperationException(string.Format(CultureInfo.InvariantCulture, Resources.ChainedExpressionSubqueryLimit, _chainedSearchMaxSubqueryItemLimit));
                 }
             }
             catch (OperationCanceledException)
             {
+                _logger.LogWarning("Request Too Costly (ConditionalRequestTooCostly)");
                 throw new RequestTooCostlyException(Core.Resources.ConditionalRequestTooCostly);
             }
 
@@ -496,6 +499,7 @@ namespace Microsoft.Health.Fhir.CosmosDb.Features.Search
                         }
                         catch (ArgumentException)
                         {
+                            _logger.LogWarning("Bad Request (InvalidFeedRange)");
                             throw new BadRequestException(Resources.InvalidFeedRange);
                         }
                     }
@@ -516,7 +520,7 @@ namespace Microsoft.Health.Fhir.CosmosDb.Features.Search
                     {
                         // ExecuteDocumentQueryAsync gave up on filling the pages. This suggests that we would have been better off querying in parallel.
 
-                        _logger.LogInformation(
+                        _logger.LogWarning(
                             "Failed to fill items, found {ItemCount}, needed {DesiredItemCount}. Physical partition count {PhysicalPartitionCount}",
                             results.Count,
                             desiredItemCount,
@@ -553,6 +557,7 @@ namespace Microsoft.Health.Fhir.CosmosDb.Features.Search
                         OperationOutcomeConstants.IssueType.NotSupported,
                         string.Format(Core.Resources.SearchCountResultsExceedLimit, count, int.MaxValue)));
 
+                _logger.LogWarning("Invalid Search Operation (SearchCountResultsExceedLimit)");
                 throw new InvalidSearchOperationException(string.Format(Core.Resources.SearchCountResultsExceedLimit, count, int.MaxValue));
             }
 

src/Microsoft.Health.Fhir.Shared.Core.UnitTests/Features/Search/SearchServiceTests.cs

@@ -12,6 +12,7 @@ using System.Threading.Tasks;
 using Hl7.Fhir.Model;
 using Hl7.Fhir.Rest;
 using Hl7.Fhir.Serialization;
+using Microsoft.Extensions.Logging.Abstractions;
 using Microsoft.Health.Fhir.Core.Exceptions;
 using Microsoft.Health.Fhir.Core.Extensions;
 using Microsoft.Health.Fhir.Core.Features;
@@ -196,7 +197,7 @@ namespace Microsoft.Health.Fhir.Core.UnitTests.Features.Search
         private class TestSearchService : SearchService
         {
             public TestSearchService(ISearchOptionsFactory searchOptionsFactory, IFhirDataStore fhirDataStore)
-                : base(searchOptionsFactory, fhirDataStore)
+                : base(searchOptionsFactory, fhirDataStore, NullLogger.Instance)
             {
                 SearchImplementation = options => null;
             }

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

@@ -89,7 +89,7 @@ namespace Microsoft.Health.Fhir.SqlServer.Features.Search
             ICompressedRawResourceConverter compressedRawResourceConverter,
             ISqlQueryHashCalculator queryHashCalculator,
             ILogger<SqlServerSearchService> logger)
-            : base(searchOptionsFactory, fhirDataStore)
+            : base(searchOptionsFactory, fhirDataStore, logger)
         {
             EnsureArg.IsNotNull(sqlRootExpressionRewriter, nameof(sqlRootExpressionRewriter));
             EnsureArg.IsNotNull(chainFlatteningRewriter, nameof(chainFlatteningRewriter));
@@ -146,8 +146,8 @@ namespace Microsoft.Health.Fhir.SqlServer.Features.Search
                         // a "special" ct so that we the subsequent request will be handled correctly.
                         var ct = new ContinuationToken(new object[]
                             {
-                                    SqlSearchConstants.SortSentinelValueForCt,
-                                    0,
+                                SqlSearchConstants.SortSentinelValueForCt,
+                                0,
                             });
 
                         searchResult = new SearchResult(searchResult.Results, ct.ToJson(), searchResult.SortOrder, searchResult.UnsupportedSearchParameters);
@@ -266,6 +266,7 @@ namespace Microsoft.Health.Fhir.SqlServer.Features.Search
                 }
                 else
                 {
+                    _logger.LogWarning("Bad Request (InvalidContinuationToken)");
                     throw new BadRequestException(Resources.InvalidContinuationToken);
                 }
             }
@@ -374,6 +375,7 @@ namespace Microsoft.Health.Fhir.SqlServer.Features.Search
                                             OperationOutcomeConstants.IssueType.NotSupported,
                                             string.Format(Core.Resources.SearchCountResultsExceedLimit, count, int.MaxValue)));
 
+                                    _logger.LogWarning("Invalid Search Operation (SearchCountResultsExceedLimit)");
                                     throw new InvalidSearchOperationException(string.Format(Core.Resources.SearchCountResultsExceedLimit, count, int.MaxValue));
                                 }
 
@@ -507,6 +509,7 @@ namespace Microsoft.Health.Fhir.SqlServer.Features.Search
 
                             if (isResultPartial)
                             {
+                                _logger.LogWarning("Bundle Partial Result (TruncatedIncludeMessage)");
                                 _requestContextAccessor.RequestContext.BundleIssues.Add(
                                     new OperationOutcomeIssue(
                                         OperationOutcomeConstants.IssueSeverity.Warning,

src/Microsoft.Health.Fhir.SqlServer/Features/Storage/SqlServerFhirDataStore.cs

@@ -251,6 +251,7 @@ namespace Microsoft.Health.Fhir.SqlServer.Features.Storage
                             continue;
                         }
 
+                        _logger.LogInformation("BadRequest: IfMatchHeaderRequiredForResource");
                         results.Add(identifier, new DataStoreOperationOutcome(new BadRequestException(string.Format(Core.Resources.IfMatchHeaderRequiredForResource, resource.ResourceTypeName))));
                         continue;
                     }