Skip to content

Commit

Permalink
Adding better logging to BadRequestExceptions (#3856)
Browse files Browse the repository at this point in the history
  • Loading branch information
@fhibf
fhibf authored May 15, 2024
1 parent 36333f8 commit b90769b
Show file tree
Hide file tree
Showing 5 changed files with 28 additions and 8 deletions.
14 changes: 12 additions & 2 deletions src/Microsoft.Health.Fhir.Core/Features/Search/SearchService.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -11,6 +11,7 @@
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;
Expand All @@ -26,19 +27,23 @@ public abstract class SearchService : ISearchService
{
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 />
Expand Down Expand Up @@ -92,6 +97,7 @@ public async Task<SearchResult> SearchHistoryAsync(
if (since != null)
{
// _at and _since cannot be both specified.
_logger.LogWarning("Invalid Search Operation (_since)");
throw new InvalidSearchOperationException(
string.Format(
CultureInfo.InvariantCulture,
Expand All @@ -102,7 +108,8 @@ public async Task<SearchResult> SearchHistoryAsync(

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,
Expand All @@ -119,6 +126,7 @@ public async Task<SearchResult> SearchHistoryAsync(
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,
Expand Down Expand Up @@ -169,6 +177,7 @@ public async Task<SearchResult> SearchHistoryAsync(
{
if (!string.Equals(sort.TrimStart('-'), KnownQueryParameterNames.LastUpdated, StringComparison.Ordinal))
{
_logger.LogWarning("Invalid Search Operation (SearchSortParameterNotSupported)");
throw new InvalidSearchOperationException(
string.Format(
CultureInfo.InvariantCulture,
Expand Down Expand Up @@ -198,6 +207,7 @@ public async Task<SearchResult> SearchHistoryAsync(

if (resource == null)
{
_logger.LogWarning("Resource Not Found (ResourceNotFoundById)");
throw new ResourceNotFoundException(string.Format(Core.Resources.ResourceNotFoundById, resourceType, resourceId));
}
}
Expand Down
9 changes: 7 additions & 2 deletions src/Microsoft.Health.Fhir.CosmosDb/Features/Search/FhirCosmosSearchService.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -55,7 +55,7 @@ public FhirCosmosSearchService(
CompartmentSearchRewriter compartmentSearchRewriter,
SmartCompartmentSearchRewriter smartCompartmentSearchRewriter,
ILogger<FhirCosmosSearchService> logger)
: base(searchOptionsFactory, fhirDataStore)
: base(searchOptionsFactory, fhirDataStore, logger)
{
EnsureArg.IsNotNull(fhirDataStore, nameof(fhirDataStore));
EnsureArg.IsNotNull(queryBuilder, nameof(queryBuilder));
Expand Down Expand Up @@ -129,6 +129,7 @@ public override async Task<SearchResult> SearchAsync(
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);
}
}
Expand Down Expand Up @@ -294,11 +295,13 @@ private async Task<Expression> RecurseChainedExpression(ChainedExpression expres
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);
}

Expand Down Expand Up @@ -496,6 +499,7 @@ protected override async Task<SearchResult> SearchForReindexInternalAsync(
}
catch (ArgumentException)
{
_logger.LogWarning("Bad Request (InvalidFeedRange)");
throw new BadRequestException(Resources.InvalidFeedRange);
}
}
Expand All @@ -516,7 +520,7 @@ protected override async Task<SearchResult> SearchForReindexInternalAsync(
{
// 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,
Expand Down Expand Up @@ -553,6 +557,7 @@ private async Task<int> ExecuteCountSearchAsync(
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));
}

Expand Down
3 changes: 2 additions & 1 deletion src/Microsoft.Health.Fhir.Shared.Core.UnitTests/Features/Search/SearchServiceTests.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -12,6 +12,7 @@
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;
Expand Down Expand Up @@ -196,7 +197,7 @@ public async Task GivenCountOnlyValue_WhenSearchingReindexResults_ThenCountSearc
private class TestSearchService : SearchService
{
public TestSearchService(ISearchOptionsFactory searchOptionsFactory, IFhirDataStore fhirDataStore)
: base(searchOptionsFactory, fhirDataStore)
: base(searchOptionsFactory, fhirDataStore, NullLogger.Instance)
{
SearchImplementation = options => null;
}
Expand Down
9 changes: 6 additions & 3 deletions src/Microsoft.Health.Fhir.SqlServer/Features/Search/SqlServerSearchService.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -89,7 +89,7 @@ public SqlServerSearchService(
ICompressedRawResourceConverter compressedRawResourceConverter,
ISqlQueryHashCalculator queryHashCalculator,
ILogger<SqlServerSearchService> logger)
: base(searchOptionsFactory, fhirDataStore)
: base(searchOptionsFactory, fhirDataStore, logger)
{
EnsureArg.IsNotNull(sqlRootExpressionRewriter, nameof(sqlRootExpressionRewriter));
EnsureArg.IsNotNull(chainFlatteningRewriter, nameof(chainFlatteningRewriter));
Expand Down Expand Up @@ -146,8 +146,8 @@ public override async Task<SearchResult> SearchAsync(SearchOptions searchOptions
// 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);
Expand Down Expand Up @@ -266,6 +266,7 @@ private async Task<SearchResult> SearchImpl(SqlSearchOptions sqlSearchOptions, s
}
else
{
_logger.LogWarning("Bad Request (InvalidContinuationToken)");
throw new BadRequestException(Resources.InvalidContinuationToken);
}
}
Expand Down Expand Up @@ -374,6 +375,7 @@ await _sqlRetryService.ExecuteSql(
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));
}
Expand Down Expand Up @@ -507,6 +509,7 @@ await _sqlRetryService.ExecuteSql(
if (isResultPartial)
{
_logger.LogWarning("Bundle Partial Result (TruncatedIncludeMessage)");
_requestContextAccessor.RequestContext.BundleIssues.Add(
new OperationOutcomeIssue(
OperationOutcomeConstants.IssueSeverity.Warning,
Expand Down
1 change: 1 addition & 0 deletions src/Microsoft.Health.Fhir.SqlServer/Features/Storage/SqlServerFhirDataStore.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -251,6 +251,7 @@ private async Task<IDictionary<DataStoreOperationIdentifier, DataStoreOperationO
continue;
}

_logger.LogInformation("BadRequest: IfMatchHeaderRequiredForResource");
results.Add(identifier, new DataStoreOperationOutcome(new BadRequestException(string.Format(Core.Resources.IfMatchHeaderRequiredForResource, resource.ResourceTypeName))));
continue;
}
Expand Down

0 comments on commit b90769b

Please sign in to comment.