Merge branch 'main' of https://github.com/almostchristian/fhir-server

Directory.Packages.props

@@ -1,7 +1,7 @@
 <Project>
   <!-- Shared dependencies versions.-->
   <PropertyGroup>
-    <HealthcareSharedPackageVersion>7.0.2</HealthcareSharedPackageVersion>
+    <HealthcareSharedPackageVersion>7.0.15</HealthcareSharedPackageVersion>
     <Hl7FhirVersion>4.3.0</Hl7FhirVersion>
   </PropertyGroup>
 
@@ -47,7 +47,7 @@
   <ItemGroup>
     <PackageVersion Include="AngleSharp" Version="1.0.4" />
     <PackageVersion Include="Azure.Extensions.AspNetCore.Configuration.Secrets" Version="1.2.2" />
-    <PackageVersion Include="Azure.Identity" Version="1.10.0" />
+    <PackageVersion Include="Azure.Identity" Version="1.10.1" />
     <PackageVersion Include="Azure.Monitor.OpenTelemetry.AspNetCore" Version="1.0.0-beta.6" />
     <PackageVersion Include="Azure.Storage.Blobs" Version="12.17.0" />
     <PackageVersion Include="coverlet.collector" Version="6.0.0" />
@@ -111,7 +111,7 @@
     <PackageVersion Include="Microsoft.SqlServer.SqlManagementObjects" Version="170.18.0" />
     <PackageVersion Include="Newtonsoft.Json.Schema" Version="3.0.15" />
     <PackageVersion Include="Newtonsoft.Json" Version="13.0.3" />
-    <PackageVersion Include="NSubstitute" Version="5.0.0" />
+    <PackageVersion Include="NSubstitute" Version="5.1.0" />
     <PackageVersion Include="Polly" Version="7.2.4" />
     <PackageVersion Include="prometheus-net.AspNetCore" Version="8.0.1" />
     <PackageVersion Include="prometheus-net.DotNetRuntime" Version="4.4.0" />

src/Microsoft.Health.Fhir.Api/Features/Audit/AuditHelper.cs

@@ -5,6 +5,7 @@
 
 using System;
 using System.Collections.Generic;
+using System.Diagnostics;
 using System.Linq;
 using System.Net;
 using System.Reflection;
@@ -80,19 +81,20 @@ public void LogExecuting(HttpContext httpContext, IClaimsExtractor claimsExtract
         /// <param name="httpContext">The HTTP context.</param>
         /// <param name="claimsExtractor">The extractor used to extract claims.</param>
         /// <param name="shouldCheckForAuthXFailure">Only emit LogExecuted messages if this is an authentication error (401), since others would already have been logged.</param>
-        public void LogExecuted(HttpContext httpContext, IClaimsExtractor claimsExtractor, bool shouldCheckForAuthXFailure = false)
+        /// <param name="durationMs">Backend duration of the request processed in milliseconds.</param>
+        public void LogExecuted(HttpContext httpContext, IClaimsExtractor claimsExtractor, bool shouldCheckForAuthXFailure = false, long? durationMs = null)
         {
             EnsureArg.IsNotNull(claimsExtractor, nameof(claimsExtractor));
             EnsureArg.IsNotNull(httpContext, nameof(httpContext));
 
             var responseStatusCode = (HttpStatusCode)httpContext.Response.StatusCode;
             if (!shouldCheckForAuthXFailure || responseStatusCode == HttpStatusCode.Unauthorized)
             {
-                Log(AuditAction.Executed, responseStatusCode, httpContext, claimsExtractor);
+                Log(AuditAction.Executed, responseStatusCode, httpContext, claimsExtractor, durationMs);
             }
         }
 
-        private void Log(AuditAction auditAction, HttpStatusCode? statusCode, HttpContext httpContext, IClaimsExtractor claimsExtractor)
+        private void Log(AuditAction auditAction, HttpStatusCode? statusCode, HttpContext httpContext, IClaimsExtractor claimsExtractor, long? durationMs = null)
         {
             IFhirRequestContext fhirRequestContext = _fhirRequestContextAccessor.RequestContext;
 
@@ -116,6 +118,13 @@ private void Log(AuditAction auditAction, HttpStatusCode? statusCode, HttpContex
                     sanitizedOperationType = UnknownOperationType;
                 }
 
+                Dictionary<string, string> additionalProperties = null;
+                if (durationMs != null)
+                {
+                    additionalProperties = new Dictionary<string, string>();
+                    additionalProperties["durationMs"] = durationMs.ToString();
+                }
+
                 _auditLogger.LogAudit(
                     auditAction,
                     operation: auditEventType,
@@ -128,7 +137,7 @@ private void Log(AuditAction auditAction, HttpStatusCode? statusCode, HttpContex
                     customHeaders: _auditHeaderReader.Read(httpContext),
                     operationType: sanitizedOperationType,
                     callerAgent: DefaultCallerAgent,
-                    additionalProperties: null);
+                    additionalProperties: additionalProperties);
             }
         }
 

src/Microsoft.Health.Fhir.Shared.Api.UnitTests/Features/Audit/AuditHelperTests.cs

@@ -8,7 +8,9 @@
 using System.Collections.ObjectModel;
 using System.Linq;
 using System.Net;
+using System.Net.Http;
 using System.Web;
+using Hl7.Fhir.Model;
 using Microsoft.AspNetCore.Http;
 using Microsoft.Extensions.Logging;
 using Microsoft.Extensions.Options;
@@ -186,6 +188,34 @@ public void GivenAuditEventType_WhenLogExecutedIsCalled_ThenAuditLogShouldBeLogg
                 callerAgent: Arg.Any<string>());
         }
 
+        [Fact]
+        public void GivenDuration_WhenLogExecutedIsCalled_ThenAdditionalPropertiesIsNotNullInAuditLog()
+        {
+            long durationMs = 1123;
+            const HttpStatusCode expectedStatusCode = HttpStatusCode.Created;
+            const string expectedResourceType = "Patient";
+
+            _fhirRequestContext.AuditEventType.Returns(AuditEventType);
+            _fhirRequestContext.ResourceType.Returns(expectedResourceType);
+            _httpContext.Response.StatusCode = (int)expectedStatusCode;
+
+            _auditHelper.LogExecuted(_httpContext, _claimsExtractor, durationMs: durationMs);
+
+            _auditLogger.Received(1).LogAudit(
+                AuditAction.Executed,
+                AuditEventType,
+                expectedResourceType,
+                Uri,
+                expectedStatusCode,
+                CorrelationId,
+                CallerIpAddressInString,
+                Claims,
+                customHeaders: _auditHeaderReader.Read(_httpContext),
+                operationType: Arg.Any<string>(),
+                callerAgent: Arg.Any<string>(),
+                additionalProperties: Arg.Is<Dictionary<string, string>>(d => d.ContainsKey("durationMs") && d.ContainsValue(durationMs.ToString())));
+        }
+
         [Fact]
         public void GivenAuditHelper_WhenLogExecutingIsCalled_ThenCallerAgentShouldAlwaysBeDefaultCallerAgent()
         {

src/Microsoft.Health.Fhir.Shared.Api.UnitTests/Features/Audit/AuditLoggingFilterAttributeTests.cs

@@ -4,6 +4,8 @@
 // -------------------------------------------------------------------------------------------------
 
 using System.Collections.Generic;
+using System.Diagnostics;
+using System.Net.Http;
 using Hl7.Fhir.Model;
 using Microsoft.AspNetCore.Http;
 using Microsoft.AspNetCore.Mvc;
@@ -56,6 +58,7 @@ public void GivenAController_WhenExecutingAction_ThenAuditLogShouldBeLogged()
         public void GivenAController_WhenExecutedAction_ThenAuditLogShouldBeLogged()
         {
             var fhirResult = new FhirResult(new Patient() { Name = { new HumanName() { Text = "TestPatient" } } }.ToResourceElement());
+            _httpContext.Items["timer"] = Stopwatch.StartNew();
 
             var resultExecutedContext = new ResultExecutedContext(
                 new ActionContext(_httpContext, new RouteData(), new ControllerActionDescriptor() { DisplayName = "Executed Context Test Descriptor" }),
@@ -65,7 +68,7 @@ public void GivenAController_WhenExecutedAction_ThenAuditLogShouldBeLogged()
 
             _filter.OnResultExecuted(resultExecutedContext);
 
-            _auditHelper.Received(1).LogExecuted(_httpContext, _claimsExtractor);
+            _auditHelper.Received(1).LogExecuted(_httpContext, _claimsExtractor, Arg.Any<bool>(), Arg.Any<long>());
         }
     }
 }

src/Microsoft.Health.Fhir.Shared.Client/FhirResponse.cs

@@ -8,6 +8,7 @@
 using System.Net;
 using System.Net.Http;
 using System.Net.Http.Headers;
+using Newtonsoft.Json.Linq;
 
 namespace Microsoft.Health.Fhir.Client
 {
@@ -52,5 +53,17 @@ public string GetRequestId()
 
             return "NO_FHIR_ACTIVITY_ID_FOR_THIS_TRANSACTION";
         }
+
+        public string GetFhirResponseDetailsAsJson()
+        {
+            JObject details = JObject.FromObject(new
+            {
+                requestUri = Response.RequestMessage?.RequestUri,
+                requestId = GetRequestId(),
+                statusCode = Response.StatusCode,
+            });
+
+            return details.ToString();
+        }
     }
 }

test/Microsoft.Health.Fhir.Shared.Tests.E2E/Rest/TransactionTests.cs

@@ -7,6 +7,7 @@
 using System.Collections.Generic;
 using System.Linq;
 using System.Net;
+using System.Security.Policy;
 using Hl7.Fhir.Model;
 using Microsoft.Health.Fhir.Client;
 using Microsoft.Health.Fhir.Core.Extensions;
@@ -316,10 +317,10 @@ public async Task GivenATransactionWithConditionalCreateAndReference_WhenExecute
             FhirResponse<Bundle> bundleResponse1 = await _client.PostBundleAsync(bundle, processingLogic: processingLogic);
 
             var patientId = bundleResponse1.Resource.Entry.First().Resource.Id;
-            ValidateReferenceToPatient(bundleResponse1.Resource.Entry[1].Resource, patientId);
+            ValidateReferenceToPatient("Bundle 1", bundleResponse1.Resource.Entry[1].Resource, patientId, bundleResponse1);
 
             FhirResponse<Bundle> bundleResponse2 = await _client.PostBundleAsync(bundle, processingLogic: processingLogic);
-            ValidateReferenceToPatient(bundleResponse2.Resource.Entry[1].Resource, patientId);
+            ValidateReferenceToPatient("Bundle 2", bundleResponse2.Resource.Entry[1].Resource, patientId, bundleResponse2);
         }
 
         [Fact]
@@ -338,7 +339,7 @@ public async Task GivenATransactionWithConditionalUpdateAndReference_WhenExecute
             FhirResponse<Bundle> bundleResponse1 = await _client.PostBundleAsync(bundle);
 
             var patientId = bundleResponse1.Resource.Entry.First().Resource.Id;
-            ValidateReferenceToPatient(bundleResponse1.Resource.Entry[1].Resource, patientId);
+            ValidateReferenceToPatient("Bundle 1", bundleResponse1.Resource.Entry[1].Resource, patientId, bundleResponse1);
 
             patient.Text = new Narrative
             {
@@ -350,19 +351,29 @@ public async Task GivenATransactionWithConditionalUpdateAndReference_WhenExecute
 
             Assert.Equal(patientId, bundleResponse2.Resource.Entry[0].Resource.Id);
             Assert.Equal("2", bundleResponse2.Resource.Entry[0].Resource.Meta.VersionId);
-            ValidateReferenceToPatient(bundleResponse2.Resource.Entry[1].Resource, patientId);
+            ValidateReferenceToPatient("Bundle 2", bundleResponse2.Resource.Entry[1].Resource, patientId, bundleResponse2);
         }
 
-        private static void ValidateReferenceToPatient(Resource resource, string patientId)
+        private static void ValidateReferenceToPatient(
+            string prefix,
+            Resource resource,
+            string patientId,
+            FhirResponse<Bundle> response)
         {
             IEnumerable<ResourceReference> imagingStudyReferences = resource.GetAllChildren<ResourceReference>();
             bool foundReference = false;
+            string expected = $"Patient/{patientId}";
 
             foreach (var reference in imagingStudyReferences)
             {
                 if (reference.Reference.StartsWith("Patient"))
                 {
-                    Assert.Equal($"Patient/{patientId}", reference.Reference);
+                    string current = reference.Reference;
+
+                    Assert.True(
+                        string.Equals(expected, current, StringComparison.Ordinal),
+                        userMessage: $"{prefix} - Expected patient reference ({expected}) is different than the current ({current}). Details: {response.GetFhirResponseDetailsAsJson()}");
+
                     foundReference = true;
                 }
             }