Batch oversized bulk operation audit logs

src/Microsoft.Health.Fhir.Shared.Core.UnitTests/Features/Persistence/BulkOperationAuditLogHelperTests.cs

@@ -0,0 +1,216 @@
+// -------------------------------------------------------------------------------------------------
+// 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.Collections.Generic;
+using System.Linq;
+using System.Net;
+using System.Threading.Tasks;
+using Microsoft.Health.Core.Features.Audit;
+using Microsoft.Health.Fhir.Core.Features.Audit;
+using Microsoft.Health.Fhir.Core.Features.Persistence;
+using Microsoft.Health.Fhir.Tests.Common;
+using Microsoft.Health.Test.Utilities;
+using NSubstitute;
+using Xunit;
+
+namespace Microsoft.Health.Fhir.Core.UnitTests.Features.Persistence
+{
+    [Trait(Traits.OwningTeam, OwningTeam.Fhir)]
+    [Trait(Traits.Category, Categories.BulkDelete)]
+    public class BulkOperationAuditLogHelperTests
+    {
+        private const int MaxAffectedItemsSize = BulkOperationAuditLogHelper.MaxAuditLogSize - BulkOperationAuditLogHelper.AuditLogOverheadSize;
+
+        [Fact]
+        public void GivenEmptyItemsList_WhenCreatingBatches_ThenSingleEmptyBatchIsReturned()
+        {
+            var items = new List<(string resourceType, string resourceId, bool included)>();
+
+            IReadOnlyList<string> batches = BulkOperationAuditLogHelper.CreateAffectedItemBatches(items);
+
+            Assert.Single(batches);
+            Assert.Equal(string.Empty, batches[0]);
+        }
+
+        [Fact]
+        public void GivenSmallItemsList_WhenCreatingBatches_ThenSingleBatchContainsAllItems()
+        {
+            var items = new List<(string resourceType, string resourceId, bool included)>
+            {
+                ("Patient", "123", false),
+                ("Observation", "456", false),
+                ("Encounter", "789", true),
+            };
+
+            IReadOnlyList<string> batches = BulkOperationAuditLogHelper.CreateAffectedItemBatches(items);
+
+            Assert.Single(batches);
+            Assert.Contains("Patient/123", batches[0]);
+            Assert.Contains("Observation/456", batches[0]);
+            Assert.Contains("[Include] Encounter/789", batches[0]);
+        }
+
+        [Fact]
+        public void GivenLargeItemsList_WhenCreatingBatches_ThenMultipleBatchesAreCreated()
+        {
+            // Create enough items to exceed the max size
+            var items = new List<(string resourceType, string resourceId, bool included)>();
+            for (int i = 0; i < 1000; i++)
+            {
+                items.Add(("Patient", $"resource-id-{i:D10}", false));
+            }
+
+            IReadOnlyList<string> batches = BulkOperationAuditLogHelper.CreateAffectedItemBatches(items);
+
+            Assert.True(batches.Count > 1, "Expected multiple batches for a large items list.");
+
+            // Verify each batch is within the size limit
+            foreach (string batch in batches)
+            {
+                Assert.True(batch.Length <= MaxAffectedItemsSize, $"Batch length {batch.Length} exceeds max size {MaxAffectedItemsSize}.");
+            }
+
+            // Verify all items are present across all batches
+            string allBatches = string.Concat(batches);
+            for (int i = 0; i < 1000; i++)
+            {
+                Assert.Contains($"Patient/resource-id-{i:D10}", allBatches);
+            }
+        }
+
+        [Fact]
+        public void GivenItemsExactlyAtLimit_WhenCreatingBatches_ThenSingleBatchIsReturned()
+        {
+            // Build items that fit exactly within the limit
+            var items = new List<(string resourceType, string resourceId, bool included)>();
+            int currentLength = 0;
+
+            for (int i = 0; ; i++)
+            {
+                string nextItem = (i == 0 ? string.Empty : ", ") + "Patient/id" + i;
+                if (currentLength + nextItem.Length > MaxAffectedItemsSize)
+                {
+                    break;
+                }
+
+                items.Add(("Patient", "id" + i, false));
+                currentLength += nextItem.Length;
+            }
+
+            IReadOnlyList<string> batches = BulkOperationAuditLogHelper.CreateAffectedItemBatches(items);
+
+            Assert.Single(batches);
+            Assert.True(batches[0].Length <= MaxAffectedItemsSize);
+        }
+
+        [Fact]
+        public void GivenIncludedItems_WhenCreatingBatches_ThenIncludeTagIsPreserved()
+        {
+            var items = new List<(string resourceType, string resourceId, bool included)>
+            {
+                ("Patient", "1", true),
+                ("Observation", "2", false),
+                ("Patient", "3", true),
+            };
+
+            IReadOnlyList<string> batches = BulkOperationAuditLogHelper.CreateAffectedItemBatches(items);
+
+            Assert.Single(batches);
+            Assert.Contains("[Include] Patient/1", batches[0]);
+            Assert.DoesNotContain("[Include] Observation/2", batches[0]);
+            Assert.Contains("Observation/2", batches[0]);
+            Assert.Contains("[Include] Patient/3", batches[0]);
+        }
+
+        [Fact]
+        public void GivenBatchesSplit_WhenCreatingBatches_ThenNoBatchStartsWithComma()
+        {
+            // Create enough items to force multiple batches
+            var items = new List<(string resourceType, string resourceId, bool included)>();
+            for (int i = 0; i < 1000; i++)
+            {
+                items.Add(("Patient", $"resource-id-{i:D10}", false));
+            }
+
+            IReadOnlyList<string> batches = BulkOperationAuditLogHelper.CreateAffectedItemBatches(items);
+
+            Assert.True(batches.Count > 1);
+
+            // No batch should start with ", "
+            foreach (string batch in batches)
+            {
+                Assert.False(batch.StartsWith(", "), "Batch should not start with a leading comma separator.");
+            }
+        }
+
+        [Fact]
+        public void GivenSingleLargeItem_WhenCreatingBatches_ThenItemIsInOwnBatch()
+        {
+            // A single item with a very long ID - should still be included even if it exceeds max
+            string longId = new string('x', MaxAffectedItemsSize);
+            var items = new List<(string resourceType, string resourceId, bool included)>
+            {
+                ("Patient", longId, false),
+            };
+
+            IReadOnlyList<string> batches = BulkOperationAuditLogHelper.CreateAffectedItemBatches(items);
+
+            Assert.Single(batches);
+            Assert.Contains($"Patient/{longId}", batches[0]);
+        }
+
+        [Fact]
+        public void GivenItemsThatCauseSplit_WhenCreatingBatches_ThenNoItemsAreLost()
+        {
+            var items = new List<(string resourceType, string resourceId, bool included)>();
+            for (int i = 0; i < 2000; i++)
+            {
+                items.Add(("Patient", $"id-{i}", i % 3 == 0));
+            }
+
+            IReadOnlyList<string> batches = BulkOperationAuditLogHelper.CreateAffectedItemBatches(items);
+
+            // Verify no items are lost by counting occurrences
+            string allContent = string.Concat(batches);
+            for (int i = 0; i < 2000; i++)
+            {
+                Assert.Contains($"Patient/id-{i}", allContent);
+            }
+        }
+
+        internal static async Task WaitForAuditLogCall(IAuditLogger auditLogger, int timeoutMs = 5000, int pollIntervalMs = 50)
+        {
+            int elapsed = 0;
+            while (elapsed < timeoutMs)
+            {
+                try
+                {
+                    auditLogger.Received().LogAudit(
+                        Arg.Any<AuditAction>(),
+                        Arg.Any<string>(),
+                        Arg.Any<string>(),
+                        Arg.Any<Uri>(),
+                        Arg.Any<HttpStatusCode?>(),
+                        Arg.Any<string>(),
+                        Arg.Any<string>(),
+                        Arg.Any<IReadOnlyCollection<KeyValuePair<string, string>>>(),
+                        Arg.Any<IReadOnlyDictionary<string, string>>(),
+                        Arg.Any<string>(),
+                        Arg.Any<string>(),
+                        Arg.Is<IReadOnlyDictionary<string, string>>(d => d.ContainsKey("Affected Items")));
+                    return;
+                }
+                catch (NSubstitute.Exceptions.ReceivedCallsException)
+                {
+                    await Task.Delay(pollIntervalMs);
+                    elapsed += pollIntervalMs;
+                }
+            }
+
+            Assert.Fail("Timed out waiting for expected call to AuditLogger.LogAudit with 'Affected Items' property.");
+        }
+    }
+}

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

@@ -0,0 +1,159 @@
+// -------------------------------------------------------------------------------------------------
+// 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.Collections.Generic;
+using System.Net;
+using System.Threading;
+using System.Threading.Tasks;
+using Hl7.Fhir.Model;
+using Hl7.Fhir.Serialization;
+using Microsoft.Extensions.Logging;
+using Microsoft.Extensions.Options;
+using Microsoft.Extensions.Primitives;
+using Microsoft.Health.Core.Features.Audit;
+using Microsoft.Health.Extensions.DependencyInjection;
+using Microsoft.Health.Fhir.Core.Configs;
+using Microsoft.Health.Fhir.Core.Extensions;
+using Microsoft.Health.Fhir.Core.Features.Audit;
+using Microsoft.Health.Fhir.Core.Features.Conformance;
+using Microsoft.Health.Fhir.Core.Features.Context;
+using Microsoft.Health.Fhir.Core.Features.Operations;
+using Microsoft.Health.Fhir.Core.Features.Persistence;
+using Microsoft.Health.Fhir.Core.Features.Search;
+using Microsoft.Health.Fhir.Core.Features.Search.Parameters;
+using Microsoft.Health.Fhir.Core.Messages.Delete;
+using Microsoft.Health.Fhir.Core.Models;
+using Microsoft.Health.Fhir.Core.Registration;
+using Microsoft.Health.Fhir.Core.UnitTests.Features.Persistence;
+using Microsoft.Health.Fhir.Tests.Common;
+using Microsoft.Health.Fhir.ValueSets;
+using Microsoft.Health.Test.Utilities;
+using NSubstitute;
+using Xunit;
+using Task = System.Threading.Tasks.Task;
+
+namespace Microsoft.Health.Fhir.Core.UnitTests.Features.Resources.Delete
+{
+    [Trait(Traits.OwningTeam, OwningTeam.Fhir)]
+    [Trait(Traits.Category, Categories.BulkDelete)]
+    public class DeletionServiceTests
+    {
+        private readonly IResourceWrapperFactory _resourceWrapperFactory = Substitute.For<IResourceWrapperFactory>();
+        private readonly Lazy<IConformanceProvider> _conformanceProvider = new Lazy<IConformanceProvider>(() => Substitute.For<IConformanceProvider>());
+        private readonly IDeletionServiceDataStoreFactory _dataStoreFactory = Substitute.For<IDeletionServiceDataStoreFactory>();
+        private readonly IScopeProvider<ISearchService> _searchServiceFactory = Substitute.For<IScopeProvider<ISearchService>>();
+        private readonly ResourceIdProvider _resourceIdProvider = Substitute.For<ResourceIdProvider>();
+        private readonly FhirRequestContextAccessor _contextAccessor = Substitute.For<FhirRequestContextAccessor>();
+        private readonly IAuditLogger _auditLogger = Substitute.For<IAuditLogger>();
+        private readonly IFhirRuntimeConfiguration _fhirRuntimeConfiguration = Substitute.For<IFhirRuntimeConfiguration>();
+        private readonly ISearchParameterOperations _searchParameterOperations = Substitute.For<ISearchParameterOperations>();
+        private readonly IResourceDeserializer _resourceDeserializer = Substitute.For<IResourceDeserializer>();
+        private readonly ILogger<DeletionService> _logger = Substitute.For<ILogger<DeletionService>>();
+        private readonly DeletionService _service;
+
+        public DeletionServiceTests()
+        {
+            var config = new CoreFeatureConfiguration();
+            var configuration = Options.Create(config);
+
+            var dummyRequestContext = new FhirRequestContext(
+                "DELETE",
+                "https://localhost/Patient",
+                "https://localhost/",
+                Guid.NewGuid().ToString(),
+                new Dictionary<string, StringValues>(),
+                new Dictionary<string, StringValues>());
+            _contextAccessor.RequestContext.Returns(dummyRequestContext);
+
+            _service = new DeletionService(
+                _resourceWrapperFactory,
+                _conformanceProvider,
+                _dataStoreFactory,
+                _searchServiceFactory,
+                _resourceIdProvider,
+                _contextAccessor,
+                _auditLogger,
+                configuration,
+                _fhirRuntimeConfiguration,
+                _searchParameterOperations,
+                _resourceDeserializer,
+                _logger);
+        }
+
+        [Fact]
+        public async Task GivenBulkHardDelete_WhenResourcesAreDeleted_ThenAuditLoggerIsCalledWithBatchedAffectedItems()
+        {
+            // Arrange
+            var resourceType = "Patient";
+            var parameters = new List<Tuple<string, string>>()
+            {
+                Tuple.Create("_lastUpdated", "2000-01-01T00:00:00Z"),
+            };
+
+            var request = new ConditionalDeleteResourceRequest(
+                resourceType,
+                parameters,
+                DeleteOperation.HardDelete,
+                maxDeleteCount: 10,
+                deleteAll: false);
+
+            var searchService = Substitute.For<ISearchService>();
+            var scopedSearchService = Substitute.For<IScoped<ISearchService>>();
+            scopedSearchService.Value.Returns(searchService);
+            _searchServiceFactory.Invoke().Returns(scopedSearchService);
+
+            var entries = new List<SearchResultEntry>();
+            for (int i = 0; i < 3; i++)
+            {
+                var resource = Samples.GetDefaultPatient().ToPoco<Patient>();
+                resource.Id = $"id-{i}";
+                resource.VersionId = "1";
+
+                var resourceElement = resource.ToResourceElement();
+                var rawResource = new RawResource(resource.ToJson(), FhirResourceFormat.Json, isMetaSet: false);
+                var resourceRequest = Substitute.For<ResourceRequest>();
+                var compartmentIndices = Substitute.For<CompartmentIndices>();
+                var wrapper = new ResourceWrapper(resourceElement, rawResource, resourceRequest, false, null, compartmentIndices, new List<KeyValuePair<string, string>>(), "hash");
+                entries.Add(new SearchResultEntry(wrapper, SearchEntryMode.Match));
+            }
+
+            searchService.SearchAsync(
+                Arg.Any<string>(),
+                Arg.Any<IReadOnlyList<Tuple<string, string>>>(),
+                Arg.Any<CancellationToken>(),
+                Arg.Any<bool>(),
+                Arg.Any<ResourceVersionType>(),
+                Arg.Any<bool>(),
+                Arg.Any<bool>()).Returns(
+                Task.FromResult(new SearchResult(entries, null, null, Array.Empty<Tuple<string, string>>())));
+
+            var fhirDataStore = Substitute.For<IFhirDataStore>();
+            var scopedDataStore = new DeletionServiceScopedDataStore(fhirDataStore);
+            _dataStoreFactory.GetScopedDataStore().Returns(scopedDataStore);
+
+            // Act
+            await _service.DeleteMultipleAsync(request, CancellationToken.None);
+
+            // Wait for Task.Run-based audit logging to complete (poll for the expected call)
+            await BulkOperationAuditLogHelperTests.WaitForAuditLogCall(_auditLogger);
+
+            // Assert - verify audit logger was called with "Affected Items" property (produced by BulkOperationAuditLogHelper)
+            _auditLogger.Received().LogAudit(
+                Arg.Any<AuditAction>(),
+                Arg.Any<string>(),
+                Arg.Any<string>(),
+                Arg.Any<Uri>(),
+                Arg.Any<HttpStatusCode?>(),
+                Arg.Any<string>(),
+                Arg.Any<string>(),
+                Arg.Any<IReadOnlyCollection<KeyValuePair<string, string>>>(),
+                Arg.Any<IReadOnlyDictionary<string, string>>(),
+                Arg.Any<string>(),
+                Arg.Any<string>(),
+                Arg.Is<IReadOnlyDictionary<string, string>>(d => d.ContainsKey("Affected Items")));
+        }
+    }
+}