From b90769b5992898d167090073b9e311cd0f0e47be Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Fernando=20Henrique=20Inoc=C3=AAncio=20Borba=20Ferreira?= Date: Wed, 15 May 2024 10:25:23 -0700 Subject: [PATCH] Adding better logging to BadRequestExceptions (#3856) --- .../Features/Search/SearchService.cs | 14 ++++++++++++-- .../Features/Search/FhirCosmosSearchService.cs | 9 +++++++-- .../Features/Search/SearchServiceTests.cs | 3 ++- .../Features/Search/SqlServerSearchService.cs | 9 ++++++--- .../Features/Storage/SqlServerFhirDataStore.cs | 1 + 5 files changed, 28 insertions(+), 8 deletions(-) diff --git a/src/Microsoft.Health.Fhir.Core/Features/Search/SearchService.cs b/src/Microsoft.Health.Fhir.Core/Features/Search/SearchService.cs index 174a0bafd..523e1159e 100644 --- a/src/Microsoft.Health.Fhir.Core/Features/Search/SearchService.cs +++ b/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; /// /// Initializes a new instance of the class. /// /// The search options factory. /// The data store - protected SearchService(ISearchOptionsFactory searchOptionsFactory, IFhirDataStore fhirDataStore) + /// Logger + 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; } /// @@ -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)); } } diff --git a/src/Microsoft.Health.Fhir.CosmosDb/Features/Search/FhirCosmosSearchService.cs b/src/Microsoft.Health.Fhir.CosmosDb/Features/Search/FhirCosmosSearchService.cs index 992050d76..4e9f1f940 100644 --- a/src/Microsoft.Health.Fhir.CosmosDb/Features/Search/FhirCosmosSearchService.cs +++ b/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 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)); } diff --git a/src/Microsoft.Health.Fhir.Shared.Core.UnitTests/Features/Search/SearchServiceTests.cs b/src/Microsoft.Health.Fhir.Shared.Core.UnitTests/Features/Search/SearchServiceTests.cs index 62b62ebcb..861d49385 100644 --- a/src/Microsoft.Health.Fhir.Shared.Core.UnitTests/Features/Search/SearchServiceTests.cs +++ b/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; } diff --git a/src/Microsoft.Health.Fhir.SqlServer/Features/Search/SqlServerSearchService.cs b/src/Microsoft.Health.Fhir.SqlServer/Features/Search/SqlServerSearchService.cs index 174455042..77feee8dc 100644 --- a/src/Microsoft.Health.Fhir.SqlServer/Features/Search/SqlServerSearchService.cs +++ b/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 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, diff --git a/src/Microsoft.Health.Fhir.SqlServer/Features/Storage/SqlServerFhirDataStore.cs b/src/Microsoft.Health.Fhir.SqlServer/Features/Storage/SqlServerFhirDataStore.cs index 7a28e0f42..7856ee67a 100644 --- a/src/Microsoft.Health.Fhir.SqlServer/Features/Storage/SqlServerFhirDataStore.cs +++ b/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; }