diff --git a/Directory.Packages.props b/Directory.Packages.props index 3ca6d7b3d7..6faccaf1a8 100644 --- a/Directory.Packages.props +++ b/Directory.Packages.props @@ -1,7 +1,7 @@ - 7.0.2 + 7.0.15 4.3.0 @@ -47,7 +47,7 @@ - + @@ -111,7 +111,7 @@ - + diff --git a/src/Microsoft.Health.Fhir.Api/Features/Audit/AuditHelper.cs b/src/Microsoft.Health.Fhir.Api/Features/Audit/AuditHelper.cs index 7105586d30..368b868d41 100644 --- a/src/Microsoft.Health.Fhir.Api/Features/Audit/AuditHelper.cs +++ b/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,7 +81,8 @@ public void LogExecuting(HttpContext httpContext, IClaimsExtractor claimsExtract /// The HTTP context. /// The extractor used to extract claims. /// Only emit LogExecuted messages if this is an authentication error (401), since others would already have been logged. - public void LogExecuted(HttpContext httpContext, IClaimsExtractor claimsExtractor, bool shouldCheckForAuthXFailure = false) + /// Backend duration of the request processed in milliseconds. + public void LogExecuted(HttpContext httpContext, IClaimsExtractor claimsExtractor, bool shouldCheckForAuthXFailure = false, long? durationMs = null) { EnsureArg.IsNotNull(claimsExtractor, nameof(claimsExtractor)); EnsureArg.IsNotNull(httpContext, nameof(httpContext)); @@ -88,11 +90,11 @@ public void LogExecuted(HttpContext httpContext, IClaimsExtractor claimsExtracto 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 additionalProperties = null; + if (durationMs != null) + { + additionalProperties = new Dictionary(); + 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); } } diff --git a/src/Microsoft.Health.Fhir.Shared.Api.UnitTests/Features/Audit/AuditHelperTests.cs b/src/Microsoft.Health.Fhir.Shared.Api.UnitTests/Features/Audit/AuditHelperTests.cs index 01967c76b4..b826448263 100644 --- a/src/Microsoft.Health.Fhir.Shared.Api.UnitTests/Features/Audit/AuditHelperTests.cs +++ b/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()); } + [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(), + callerAgent: Arg.Any(), + additionalProperties: Arg.Is>(d => d.ContainsKey("durationMs") && d.ContainsValue(durationMs.ToString()))); + } + [Fact] public void GivenAuditHelper_WhenLogExecutingIsCalled_ThenCallerAgentShouldAlwaysBeDefaultCallerAgent() { diff --git a/src/Microsoft.Health.Fhir.Shared.Api.UnitTests/Features/Audit/AuditLoggingFilterAttributeTests.cs b/src/Microsoft.Health.Fhir.Shared.Api.UnitTests/Features/Audit/AuditLoggingFilterAttributeTests.cs index 09f0650407..0858fd28db 100644 --- a/src/Microsoft.Health.Fhir.Shared.Api.UnitTests/Features/Audit/AuditLoggingFilterAttributeTests.cs +++ b/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(), Arg.Any()); } } } diff --git a/src/Microsoft.Health.Fhir.Shared.Client/FhirResponse.cs b/src/Microsoft.Health.Fhir.Shared.Client/FhirResponse.cs index 6a35ea9340..1b290985e2 100644 --- a/src/Microsoft.Health.Fhir.Shared.Client/FhirResponse.cs +++ b/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(); + } } } diff --git a/test/Microsoft.Health.Fhir.Shared.Tests.E2E/Rest/TransactionTests.cs b/test/Microsoft.Health.Fhir.Shared.Tests.E2E/Rest/TransactionTests.cs index 62c80bd399..4c96524137 100644 --- a/test/Microsoft.Health.Fhir.Shared.Tests.E2E/Rest/TransactionTests.cs +++ b/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 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 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 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 response) { IEnumerable imagingStudyReferences = resource.GetAllChildren(); 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; } }