[Bundles] Additional logs for client errors

src/Microsoft.Health.Fhir.Core.UnitTests/Features/Operations/BulkDelete/CreateBulkDeleteHandlerTests.cs

@@ -7,6 +7,7 @@
 using System.Collections.Generic;
 using System.Threading;
 using System.Threading.Tasks;
+using Microsoft.Extensions.Logging;
 using Microsoft.Extensions.Primitives;
 using Microsoft.Health.Core.Features.Context;
 using Microsoft.Health.Core.Features.Security.Authorization;
@@ -56,7 +57,12 @@ public CreateBulkDeleteHandlerTests()
                 requestHeaders: new Dictionary<string, StringValues>(),
                 responseHeaders: new Dictionary<string, StringValues>());
 
-            _handler = new CreateBulkDeleteHandler(_authorizationService, _queueClient, _contextAccessor, _searchService);
+            _handler = new CreateBulkDeleteHandler(
+                _authorizationService,
+                _queueClient,
+                _contextAccessor,
+                _searchService,
+                Substitute.For<ILogger<CreateBulkDeleteHandler>>());
         }
 
         [Fact]

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

@@ -10,6 +10,7 @@
 using System.Threading.Tasks;
 using EnsureThat;
 using MediatR;
+using Microsoft.Extensions.Logging;
 using Microsoft.Health.Core;
 using Microsoft.Health.Core.Features.Context;
 using Microsoft.Health.Core.Features.Security.Authorization;
@@ -32,17 +33,20 @@ public class CreateBulkDeleteHandler : IRequestHandler<CreateBulkDeleteRequest,
         private readonly IQueueClient _queueClient;
         private readonly RequestContextAccessor<IFhirRequestContext> _contextAccessor;
         private readonly ISearchService _searchService;
+        private readonly ILogger<CreateBulkDeleteHandler> _logger;
 
         public CreateBulkDeleteHandler(
             IAuthorizationService<DataActions> authorizationService,
             IQueueClient queueClient,
             RequestContextAccessor<IFhirRequestContext> contextAccessor,
-            ISearchService searchService)
+            ISearchService searchService,
+            ILogger<CreateBulkDeleteHandler> logger)
         {
             _authorizationService = EnsureArg.IsNotNull(authorizationService, nameof(authorizationService));
             _queueClient = EnsureArg.IsNotNull(queueClient, nameof(queueClient));
             _contextAccessor = EnsureArg.IsNotNull(contextAccessor, nameof(contextAccessor));
             _searchService = EnsureArg.IsNotNull(searchService, nameof(searchService));
+            _logger = EnsureArg.IsNotNull(logger, nameof(logger));
         }
 
         public async Task<CreateBulkDeleteResponse> Handle(CreateBulkDeleteRequest request, CancellationToken cancellationToken)
@@ -65,7 +69,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, count: 1);
+            await _searchService.ConditionalSearchAsync(request.ResourceType, searchParameters, cancellationToken, count: 1, logger: _logger);
             if (_contextAccessor.RequestContext?.BundleIssues?.Count > 0)
             {
                 throw new BadRequestException(_contextAccessor.RequestContext.BundleIssues.Select(issue => issue.Diagnostics).ToList());

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

@@ -116,7 +116,7 @@ private IFhirRequestContext CreateRequestContextForBundleHandlerProcessing(Bundl
             var fhirJsonParser = new FhirJsonParser();
 
             ISearchService searchService = Substitute.For<ISearchService>();
-            var resourceReferenceResolver = new ResourceReferenceResolver(searchService, new QueryStringParser());
+            var resourceReferenceResolver = new ResourceReferenceResolver(searchService, new QueryStringParser(), Substitute.For<ILogger<ResourceReferenceResolver>>());
 
             var transactionBundleValidatorLogger = Substitute.For<ILogger<TransactionBundleValidator>>();
             var transactionBundleValidator = new TransactionBundleValidator(resourceReferenceResolver, transactionBundleValidatorLogger);

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

@@ -79,8 +79,10 @@ public BundleHandlerTests()
             var fhirJsonSerializer = new FhirJsonSerializer();
             var fhirJsonParser = new FhirJsonParser();
 
+            var loggerResourceReferenceResolver = Substitute.For<ILogger<ResourceReferenceResolver>>();
+
             ISearchService searchService = Substitute.For<ISearchService>();
-            var resourceReferenceResolver = new ResourceReferenceResolver(searchService, new QueryStringParser());
+            var resourceReferenceResolver = new ResourceReferenceResolver(searchService, new QueryStringParser(), loggerResourceReferenceResolver);
 
             var transactionBundleValidatorLogger = Substitute.For<ILogger<TransactionBundleValidator>>();
             var transactionBundleValidator = new TransactionBundleValidator(resourceReferenceResolver, transactionBundleValidatorLogger);

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

@@ -7,7 +7,6 @@
 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;
@@ -31,12 +30,13 @@ public class TransactionBundleValidatorTests
     {
         private readonly ISearchService _searchService = Substitute.For<ISearchService>();
         private readonly ILogger<TransactionBundleValidator> _logger = Substitute.For<ILogger<TransactionBundleValidator>>();
+        private readonly ILogger<ResourceReferenceResolver> _loggerResourceReferenceResolver = Substitute.For<ILogger<ResourceReferenceResolver>>();
         private readonly TransactionBundleValidator _transactionBundleValidator;
         private readonly Dictionary<string, (string resourceId, string resourceType)> _idDictionary;
 
         public TransactionBundleValidatorTests()
         {
-            _transactionBundleValidator = new TransactionBundleValidator(new ResourceReferenceResolver(_searchService, new QueryStringParser()), _logger);
+            _transactionBundleValidator = new TransactionBundleValidator(new ResourceReferenceResolver(_searchService, new QueryStringParser(), _loggerResourceReferenceResolver), _logger);
             _idDictionary = new Dictionary<string, (string resourceId, string resourceType)>();
         }
 

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

@@ -10,6 +10,7 @@
 using System.IO;
 using System.Linq;
 using System.Net;
+using System.Text;
 using System.Threading;
 using System.Threading.Tasks;
 using System.Transactions;
@@ -22,10 +23,7 @@
 using Microsoft.AspNetCore.Http.Extensions;
 using Microsoft.AspNetCore.Http.Features.Authentication;
 using Microsoft.AspNetCore.Http.Headers;
-using Microsoft.AspNetCore.Mvc.Infrastructure;
-using Microsoft.AspNetCore.Mvc.Routing;
 using Microsoft.AspNetCore.Routing;
-using Microsoft.AspNetCore.Routing.Template;
 using Microsoft.Extensions.Logging;
 using Microsoft.Extensions.Options;
 using Microsoft.Extensions.Primitives;
@@ -54,7 +52,6 @@
 using Microsoft.Health.Fhir.Core.Messages.Bundle;
 using Microsoft.Health.Fhir.Core.Models;
 using Microsoft.Health.Fhir.ValueSets;
-using SharpCompress.Common;
 using static Hl7.Fhir.Model.Bundle;
 using Task = System.Threading.Tasks.Task;
 
@@ -101,6 +98,16 @@ public partial class BundleHandler : IRequestHandler<BundleRequest, BundleRespon
         /// </summary>
         private static readonly string[] HeadersToAccumulate = new[] { KnownHeaders.RetryAfter, KnownHeaders.RetryAfterMilliseconds, "x-ms-session-token", "x-ms-request-charge" };
 
+        /// <summary>
+        /// Headers to propagate from the inner actions to the outer HTTP request.
+        /// </summary>
+        private static readonly string[] SuccessfullStatusCodeToAvoidAdditionalLogging = new[]
+        {
+            ((int)HttpStatusCode.OK).ToString(),
+            ((int)HttpStatusCode.Created).ToString(),
+            ((int)HttpStatusCode.Accepted).ToString(),
+        };
+
         /// <summary>
         /// Properties to propagate from the outer HTTP requests to the inner actions.
         /// </summary>
@@ -676,6 +683,8 @@ private async Task<EntryComponent> ExecuteRequestsWithSingleHttpVerbInSequenceAs
 
                 statistics.RegisterNewEntry(httpVerb, resourceContext.Index, entryComponent.Response.Status, watch.Elapsed);
 
+                LogFinalOperationOutcomeForFailedRecords(resourceContext.Index, entryComponent);
+
                 if (_bundleType.Equals(BundleType.Transaction) && entryComponent.Response.Outcome != null)
                 {
                     var errorMessage = string.Format(Api.Resources.TransactionFailed, resourceContext.Context.HttpContext.Request.Method, resourceContext.Context.HttpContext.Request.Path);
@@ -845,6 +854,46 @@ private static void SetupContexts(
             }
         }
 
+        private void LogFinalOperationOutcomeForFailedRecords(int index, EntryComponent entryComponent)
+        {
+            if (entryComponent?.Response?.Outcome == null)
+            {
+                return;
+            }
+
+            // If the result is a successful, no need to log the outcome for potential troubleshooting.
+            if (SuccessfullStatusCodeToAvoidAdditionalLogging.Contains(entryComponent.Response.Status))
+            {
+                return;
+            }
+
+            try
+            {
+                StringBuilder reason = new StringBuilder();
+                if (entryComponent.Response.Outcome is OperationOutcome operationOutcome && operationOutcome.Issue.Any())
+                {
+                    foreach (OperationOutcome.IssueComponent issue in operationOutcome.Issue)
+                    {
+                        reason.AppendLine($"{issue.Severity} / {issue.Code} / {SanitizeString(issue.Diagnostics)}");
+                    }
+                }
+                else
+                {
+                    reason.Append("Reason is not defined.");
+                }
+
+                _logger.LogInformation(
+                    "Throubleshoot Outcome {Index}: {HttpStatus}. Reason: {Reason}",
+                    index,
+                    entryComponent.Response.Status,
+                    reason.ToString());
+            }
+            catch (Exception ex)
+            {
+                _logger.LogError(ex, $"Throubleshoot Outcome {index}: Error while logging the final operation outcome for failed records. This error will not block the bundle processing.");
+            }
+        }
+
         private void PopulateReferenceIdDictionary(IReadOnlyCollection<EntryComponent> bundleEntries, IDictionary<string, (string resourceId, string resourceType)> idDictionary)
         {
             foreach (EntryComponent entry in bundleEntries)
@@ -888,6 +937,14 @@ private static OperationOutcome CreateOperationOutcome(OperationOutcome.IssueSev
             };
         }
 
+        private static string SanitizeString(string input)
+        {
+            return input
+                .Replace(Environment.NewLine, string.Empty, StringComparison.OrdinalIgnoreCase)
+                .Replace("\r", string.Empty, StringComparison.OrdinalIgnoreCase)
+                .Replace("\n", string.Empty, StringComparison.OrdinalIgnoreCase);
+        }
+
         private BundleHandlerStatistics CreateNewBundleHandlerStatistics(BundleProcessingLogic processingLogic)
         {
             BundleHandlerStatistics statistics = new BundleHandlerStatistics(_bundleType, processingLogic, _optimizedQuerySet, _requestCount);

src/Microsoft.Health.Fhir.Shared.Core.UnitTests/Features/Resources/ResourceHandlerTests.cs

@@ -8,15 +8,13 @@
 using System.Linq;
 using System.Net.Http;
 using System.Threading;
-using Castle.Core.Logging;
 using Hl7.Fhir.ElementModel;
 using Hl7.Fhir.Model;
 using Hl7.Fhir.Serialization;
 using MediatR;
 using Microsoft.Extensions.DependencyInjection;
 using Microsoft.Extensions.Logging;
 using Microsoft.Extensions.Primitives;
-using Microsoft.Health.Core.Features.Context;
 using Microsoft.Health.Core.Features.Security.Authorization;
 using Microsoft.Health.Extensions.DependencyInjection;
 using Microsoft.Health.Fhir.Core.Exceptions;
@@ -114,7 +112,7 @@ public ResourceHandlerTests()
 
             var contextAccessor = Substitute.For<FhirRequestContextAccessor>();
             contextAccessor.RequestContext = new FhirRequestContext("method", "http://localhost", "http://localhost", "id", new Dictionary<string, StringValues>(), new Dictionary<string, StringValues>());
-            var referenceResolver = new ResourceReferenceResolver(_searchService, new TestQueryStringParser());
+            var referenceResolver = new ResourceReferenceResolver(_searchService, new TestQueryStringParser(), Substitute.For<ILogger<ResourceReferenceResolver>>());
             _resourceIdProvider = new ResourceIdProvider();
 
             var auditLogger = Substitute.For<IAuditLogger>();

src/Microsoft.Health.Fhir.Shared.Core.UnitTests/Features/Resources/ResourceReferenceResolverTests.cs

@@ -8,6 +8,7 @@
 using System.Linq;
 using System.Threading;
 using Hl7.Fhir.Model;
+using Microsoft.Extensions.Logging;
 using Microsoft.Health.Fhir.Core.Exceptions;
 using Microsoft.Health.Fhir.Core.Extensions;
 using Microsoft.Health.Fhir.Core.Features.Persistence;
@@ -32,7 +33,7 @@ public class ResourceReferenceResolverTests
 
         public ResourceReferenceResolverTests()
         {
-            _referenceResolver = new ResourceReferenceResolver(_searchService, new TestQueryStringParser());
+            _referenceResolver = new ResourceReferenceResolver(_searchService, new TestQueryStringParser(), Substitute.For<ILogger<ResourceReferenceResolver>>());
         }
 
         [Fact]

src/Microsoft.Health.Fhir.Shared.Core/Features/Resources/ConditionalResourceHandler.cs

@@ -4,7 +4,6 @@
 // -------------------------------------------------------------------------------------------------
 
 using System;
-using System.Collections.Generic;
 using System.Globalization;
 using System.Linq;
 using System.Threading;
@@ -75,7 +74,7 @@ public async Task<TResponse> Handle(TRequest request, CancellationToken cancella
             else
             {
                 // Multiple matches: The server returns a 412 Precondition Failed error indicating the client's criteria were not selective enough
-                _logger.LogInformation("PreconditionFailed - Conditional handler: Multiple Matches Found. ResourceType={ResourceType}, NumberOfMatches={NumberOfMatches}", request.ResourceType, count);
+                _logger.LogInformation("PreconditionFailed: Conditional handler: Multiple Matches Found. ResourceType={ResourceType}, NumberOfMatches={NumberOfMatches}", request.ResourceType, count);
                 throw new PreconditionFailedException(string.Format(CultureInfo.InvariantCulture, Core.Resources.ConditionalOperationNotSelectiveEnough, request.ResourceType));
             }
         }

src/Microsoft.Health.Fhir.Shared.Core/Features/Resources/Create/ConditionalCreateResourceValidator.cs

@@ -5,20 +5,22 @@
 
 using System.Globalization;
 using FluentValidation;
+using Microsoft.Extensions.Logging;
 using Microsoft.Health.Fhir.Core.Messages.Create;
 
 namespace Microsoft.Health.Fhir.Core.Features.Resources.Create
 {
     [System.Diagnostics.CodeAnalysis.SuppressMessage("Naming", "CA1710:Identifiers should have correct suffix", Justification = "Follows validator naming convention.")]
     public class ConditionalCreateResourceValidator : AbstractValidator<ConditionalCreateResourceRequest>
     {
-        public ConditionalCreateResourceValidator()
+        public ConditionalCreateResourceValidator(ILogger<ConditionalCreateResourceValidator> logger)
         {
             RuleFor(x => x.ConditionalParameters)
                 .Custom((conditionalParameters, context) =>
                 {
                     if (conditionalParameters.Count == 0)
                     {
+                        logger?.LogInformation("PreconditionFailed: ConditionalOperationNotSelectiveEnough");
                         context.AddFailure(string.Format(CultureInfo.InvariantCulture, Core.Resources.ConditionalOperationNotSelectiveEnough, context.InstanceToValidate.ResourceType));
                     }
                 });

src/Microsoft.Health.Fhir.Shared.Core/Features/Resources/Delete/ConditionalDeleteResourceValidator.cs

@@ -6,6 +6,7 @@
 using System.Globalization;
 using EnsureThat;
 using FluentValidation;
+using Microsoft.Extensions.Logging;
 using Microsoft.Extensions.Options;
 using Microsoft.Health.Fhir.Core.Configs;
 using Microsoft.Health.Fhir.Core.Messages.Delete;
@@ -16,7 +17,7 @@
     [System.Diagnostics.CodeAnalysis.SuppressMessage("Naming", "CA1710:Identifiers should have correct suffix", Justification = "Follows validator naming convention.")]
     public class ConditionalDeleteResourceValidator : AbstractValidator<ConditionalDeleteResourceRequest>
     {
-        public ConditionalDeleteResourceValidator(IOptions<CoreFeatureConfiguration> configuration, IModelInfoProvider modelInfoProvider)
+        public ConditionalDeleteResourceValidator(IOptions<CoreFeatureConfiguration> configuration, IModelInfoProvider modelInfoProvider, ILogger<ConditionalDeleteResourceValidator> logger)
         {
             EnsureArg.IsNotNull(configuration?.Value, nameof(configuration));
 
@@ -29,12 +30,13 @@
                 {
                     if (conditionalParameters.Count == 0)
                     {
+                        logger?.LogInformation("PreconditionFailed: ConditionalOperationNotSelectiveEnough");
                         context.AddFailure(string.Format(CultureInfo.InvariantCulture, Core.Resources.ConditionalOperationNotSelectiveEnough, context.InstanceToValidate.ResourceType));
                     }
                 });
 
             RuleFor(x => x.MaxDeleteCount)
                 .InclusiveBetween(1, configuration.Value.ConditionalDeleteMaxItems)
                 .WithMessage(string.Format(CultureInfo.InvariantCulture, Core.Resources.ConditionalDeleteCountOutOfRange, 1, configuration.Value.ConditionalDeleteMaxItems));
         }
     }

src/Microsoft.Health.Fhir.Shared.Core/Features/Resources/Delete/DeletionService.cs

@@ -127,7 +127,8 @@ public async Task<long> DeleteMultipleAsync(ConditionalDeleteResourceRequest req
                     cancellationToken,
                     request.DeleteAll ? searchCount : request.MaxDeleteCount,
                     versionType: request.VersionType,
-                    onlyIds: true);
+                    onlyIds: true,
+                    logger: _logger);
             }
 
             long numDeleted = 0;
@@ -179,7 +180,8 @@ public async Task<long> DeleteMultipleAsync(ConditionalDeleteResourceRequest req
                                 request.DeleteAll ? searchCount : (int)(request.MaxDeleteCount - numQueuedForDeletion),
                                 ct,
                                 request.VersionType,
-                                onlyIds: true);
+                                onlyIds: true,
+                                logger: _logger);
                         }
                     }
                     else