From 384d6618bb385abc1981a974e24aaf20a3527f48 Mon Sep 17 00:00:00 2001 From: Karthik Balasubramanian Date: Fri, 8 Dec 2023 10:01:15 -0800 Subject: [PATCH] Pass correct severity level for shoeboxlogs (#3249) * Add failed instaces while update to shoebox logs * Remove obsolete code * Add more logs to shoebox * Fix comment * Fix tests * Pass correct severity level for shoeboxlogs * Log audit * Fix tests * Add service --- .../Features/Storage/BlobFileStore.cs | 2 +- .../Diagnostic/LogForwarderExtensionsTests.cs | 17 ++++--- .../Features/Audit/AuditEventSubType.cs | 2 + .../Diagnostic/LogForwarderExtensions.cs | 40 ++++++++++++----- .../Features/Store/StoreService.cs | 3 +- .../Update/UpdateInstanceOperationService.cs | 3 +- .../Update/UpdateDurableFunctionTests.cs | 3 ++ .../ServiceCollectionExtensions.cs | 4 +- .../UpdateDurableFunction.Orchestration.cs | 45 +++++++++++++++++-- .../Update/UpdateDurableFunction.cs | 4 ++ 10 files changed, 97 insertions(+), 26 deletions(-) diff --git a/src/Microsoft.Health.Dicom.Blob/Features/Storage/BlobFileStore.cs b/src/Microsoft.Health.Dicom.Blob/Features/Storage/BlobFileStore.cs index 3d3fc27f1d..d61f224bb8 100644 --- a/src/Microsoft.Health.Dicom.Blob/Features/Storage/BlobFileStore.cs +++ b/src/Microsoft.Health.Dicom.Blob/Features/Storage/BlobFileStore.cs @@ -243,7 +243,7 @@ await ExecuteAsync( fileProperties.Path, fileProperties.ETag); - _telemetryClient.ForwardLogTrace(message, partition, fileProperties); + _telemetryClient.ForwardLogTrace(message, partition, fileProperties, ApplicationInsights.DataContracts.SeverityLevel.Warning); _logger.LogInformation( "Can not delete blob in external store as it has changed or been deleted. File from watermark: '{Version}' and PartitionKey: {PartitionKey}. Dangling SQL Index detected. Will not retry", diff --git a/src/Microsoft.Health.Dicom.Core.UnitTests/Features/Diagnostic/LogForwarderExtensionsTests.cs b/src/Microsoft.Health.Dicom.Core.UnitTests/Features/Diagnostic/LogForwarderExtensionsTests.cs index dc678fd048..0a87a0a794 100644 --- a/src/Microsoft.Health.Dicom.Core.UnitTests/Features/Diagnostic/LogForwarderExtensionsTests.cs +++ b/src/Microsoft.Health.Dicom.Core.UnitTests/Features/Diagnostic/LogForwarderExtensionsTests.cs @@ -1,4 +1,4 @@ -// ------------------------------------------------------------------------------------------------- +// ------------------------------------------------------------------------------------------------- // Copyright (c) Microsoft Corporation. All rights reserved. // Licensed under the MIT License (MIT). See LICENSE in the repo root for license information. // ------------------------------------------------------------------------------------------------- @@ -120,14 +120,15 @@ public void GivenClientUsingForwardTelemetry_whenForwardOperationLogTraceWithSiz var operationId = Guid.NewGuid().ToString(); var input = "input"; var message = "a message"; - telemetryClient.ForwardOperationLogTrace(message, operationId, input); + telemetryClient.ForwardOperationLogTrace(message, operationId, input, "update"); Assert.Single(channel.Items); #pragma warning disable CS0618 // Type or member is obsolete - Assert.Equal(3, channel.Items[0].Context.Properties.Count); + Assert.Equal(4, channel.Items[0].Context.Properties.Count); Assert.Equal(Boolean.TrueString, channel.Items[0].Context.Properties["forwardLog"]); Assert.Equal(operationId, channel.Items[0].Context.Properties["dicomAdditionalInformation_operationId"]); Assert.Equal(input, channel.Items[0].Context.Properties["dicomAdditionalInformation_input"]); + Assert.Equal("update", channel.Items[0].Context.Properties["operationName"]); #pragma warning restore CS0618 // Type or member is obsolete } @@ -141,22 +142,24 @@ public void GivenClientUsingForwardTelemetry_whenForwardOperationLogTraceWithSiz var expectedSecondItemInput = "b".PadRight(32 * 1024); // split occurs at 32 kb var fullInput = expectedFirstItemInput + expectedSecondItemInput; var message = "a message"; - telemetryClient.ForwardOperationLogTrace(message, operationId, fullInput); + telemetryClient.ForwardOperationLogTrace(message, operationId, fullInput, "update"); Assert.Equal(2, channel.Items.Count); #pragma warning disable CS0618 // Type or member is obsolete var firstItem = channel.Items[0]; - Assert.Equal(3, firstItem.Context.Properties.Count); + Assert.Equal(4, firstItem.Context.Properties.Count); Assert.Equal(Boolean.TrueString, firstItem.Context.Properties["forwardLog"]); Assert.Equal(operationId, firstItem.Context.Properties["dicomAdditionalInformation_operationId"]); Assert.Equal(expectedFirstItemInput, firstItem.Context.Properties["dicomAdditionalInformation_input"]); + Assert.Equal("update", firstItem.Context.Properties["operationName"]); var secondItem = channel.Items[1]; - Assert.Equal(3, secondItem.Context.Properties.Count); + Assert.Equal(4, secondItem.Context.Properties.Count); Assert.Equal(Boolean.TrueString, secondItem.Context.Properties["forwardLog"]); Assert.Equal(operationId, secondItem.Context.Properties["dicomAdditionalInformation_operationId"]); Assert.Equal(expectedSecondItemInput, secondItem.Context.Properties["dicomAdditionalInformation_input"]); + Assert.Equal("update", firstItem.Context.Properties["operationName"]); #pragma warning restore CS0618 // Type or member is obsolete } @@ -175,4 +178,4 @@ private static (TelemetryClient, MockTelemetryChannel) CreateTelemetryClientWith return (new TelemetryClient(configuration), channel); } -} \ No newline at end of file +} diff --git a/src/Microsoft.Health.Dicom.Core/Features/Audit/AuditEventSubType.cs b/src/Microsoft.Health.Dicom.Core/Features/Audit/AuditEventSubType.cs index d771cf9516..1ca290e86b 100644 --- a/src/Microsoft.Health.Dicom.Core/Features/Audit/AuditEventSubType.cs +++ b/src/Microsoft.Health.Dicom.Core/Features/Audit/AuditEventSubType.cs @@ -59,4 +59,6 @@ public static class AuditEventSubType public const string BulkImportStore = "bulk-import-store"; public const string UpdateStudy = "update-study"; + + public const string UpdateStudyOperation = "update-study-operation"; } diff --git a/src/Microsoft.Health.Dicom.Core/Features/Diagnostic/LogForwarderExtensions.cs b/src/Microsoft.Health.Dicom.Core/Features/Diagnostic/LogForwarderExtensions.cs index 389740bead..7a28646da1 100644 --- a/src/Microsoft.Health.Dicom.Core/Features/Diagnostic/LogForwarderExtensions.cs +++ b/src/Microsoft.Health.Dicom.Core/Features/Diagnostic/LogForwarderExtensions.cs @@ -21,6 +21,7 @@ internal static class LogForwarderExtensions private const int MaxShoeboxPropertySize = 32 * 1024; private const string ForwardLogFlag = "forwardLog"; private const string Prefix = "dicomAdditionalInformation_"; + private const string OperationName = "operationName"; private const string StudyInstanceUID = $"{Prefix}studyInstanceUID"; private const string SeriesInstanceUID = $"{Prefix}seriesInstanceUID"; private const string SOPInstanceUID = $"{Prefix}sopInstanceUID"; @@ -36,16 +37,18 @@ internal static class LogForwarderExtensions /// client to use to emit the trace /// message to set on the trace log /// identifier to use to set UIDs on log and telemetry properties + /// Severity level of the message public static void ForwardLogTrace( this TelemetryClient telemetryClient, string message, - InstanceIdentifier instanceIdentifier) + InstanceIdentifier instanceIdentifier, + SeverityLevel severityLevel = SeverityLevel.Information) { EnsureArg.IsNotNull(telemetryClient, nameof(telemetryClient)); EnsureArg.IsNotNull(message, nameof(message)); EnsureArg.IsNotNull(instanceIdentifier, nameof(instanceIdentifier)); - var telemetry = new TraceTelemetry(message); + var telemetry = new TraceTelemetry(message, severityLevel); telemetry.Properties.Add(StudyInstanceUID, instanceIdentifier.StudyInstanceUid); telemetry.Properties.Add(SeriesInstanceUID, instanceIdentifier.SeriesInstanceUid); telemetry.Properties.Add(SOPInstanceUID, instanceIdentifier.SopInstanceUid); @@ -64,14 +67,16 @@ public static void ForwardLogTrace( /// NOTE - do not use this if reporting on any specific instance. Only use as high level remarks. Attempt to use identifiers wherever possible /// client to use to emit the trace /// message to set on the trace log + /// Severity level of the message public static void ForwardLogTrace( this TelemetryClient telemetryClient, - string message) + string message, + SeverityLevel severityLevel = SeverityLevel.Information) { EnsureArg.IsNotNull(telemetryClient, nameof(telemetryClient)); EnsureArg.IsNotNull(message, nameof(message)); - var telemetry = new TraceTelemetry(message); + var telemetry = new TraceTelemetry(message, severityLevel); telemetry.Properties.Add(ForwardLogFlag, bool.TrueString); telemetryClient.TrackTrace(telemetry); @@ -84,18 +89,20 @@ public static void ForwardLogTrace( /// message to set on the trace log /// Partition within which file is residing /// File properties of file this message is regarding + /// Severity level of the message public static void ForwardLogTrace( this TelemetryClient telemetryClient, string message, Partition partition, - FileProperties fileProperties) + FileProperties fileProperties, + SeverityLevel severityLevel = SeverityLevel.Information) { EnsureArg.IsNotNull(telemetryClient, nameof(telemetryClient)); EnsureArg.IsNotNull(message, nameof(message)); EnsureArg.IsNotNull(partition, nameof(partition)); EnsureArg.IsNotNull(fileProperties, nameof(fileProperties)); - var telemetry = new TraceTelemetry(message); + var telemetry = new TraceTelemetry(message, severityLevel); telemetry.Properties.Add(ForwardLogFlag, bool.TrueString); telemetry.Properties.Add(FilePropertiesPath, fileProperties.Path); telemetry.Properties.Add(FilePropertiesETag, fileProperties.ETag); @@ -109,26 +116,32 @@ public static void ForwardLogTrace( /// /// Emits a trace log with forwarding flag set for operations and adds the required properties to telemetry. + /// For Audit shoebox the operation name are automatically populated from HttpContext. For internal operation, the operation name needs to be passed in. /// /// client to use to emit the trace /// message to set on the trace log /// operation id /// Input payload to pass to the forward logger + /// Operation name of the trace event + /// Severity level of the message public static void ForwardOperationLogTrace( this TelemetryClient telemetryClient, string message, string operationId, - string input) + string input, + string operationName, + SeverityLevel severityLevel = SeverityLevel.Information) { EnsureArg.IsNotNull(telemetryClient, nameof(telemetryClient)); EnsureArg.IsNotNull(message, nameof(message)); + EnsureArg.IsNotNull(operationId, nameof(operationId)); // Shoebox property size has a limitation of 32 KB which is why the diagnostic log is split into multiple messages - int startIndex = 0, offset = 0, inputSize = input.Length; + int startIndex = 0, inputSize = input.Length; while (startIndex < inputSize) { - offset = Math.Min(MaxShoeboxPropertySize, input.Length - startIndex); - ForwardOperationLogTraceWithSizeLimit(telemetryClient, message, operationId, input.Substring(startIndex, offset)); + int offset = Math.Min(MaxShoeboxPropertySize, input.Length - startIndex); + ForwardOperationLogTraceWithSizeLimit(telemetryClient, message, operationId, input.Substring(startIndex, offset), operationName, severityLevel); startIndex += offset; } } @@ -137,12 +150,15 @@ private static void ForwardOperationLogTraceWithSizeLimit( TelemetryClient telemetryClient, string message, string operationId, - string input) + string input, + string operationName, + SeverityLevel severityLevel) { - var telemetry = new TraceTelemetry(message); + var telemetry = new TraceTelemetry(message, severityLevel); telemetry.Properties.Add(InputPayload, input); telemetry.Properties.Add(OperationId, operationId); telemetry.Properties.Add(ForwardLogFlag, bool.TrueString); + telemetry.Properties.Add(OperationName, operationName); telemetryClient.TrackTrace(telemetry); } diff --git a/src/Microsoft.Health.Dicom.Core/Features/Store/StoreService.cs b/src/Microsoft.Health.Dicom.Core/Features/Store/StoreService.cs index 78f6cc4c1f..0f1846472c 100644 --- a/src/Microsoft.Health.Dicom.Core/Features/Store/StoreService.cs +++ b/src/Microsoft.Health.Dicom.Core/Features/Store/StoreService.cs @@ -273,7 +273,8 @@ private void DropInvalidMetadata(StoreValidationResult storeValidatorResult, Dic _telemetryClient.ForwardLogTrace( $"{message}. This attribute will not be present when retrieving study, series, or instance metadata resources, nor can it be used in searches." + " However, it will still be present when retrieving study, series, or instance resources.", - identifier); + identifier, + ApplicationInsights.DataContracts.SeverityLevel.Warning); } } } diff --git a/src/Microsoft.Health.Dicom.Core/Features/Update/UpdateInstanceOperationService.cs b/src/Microsoft.Health.Dicom.Core/Features/Update/UpdateInstanceOperationService.cs index 4086ff0661..8683d18736 100644 --- a/src/Microsoft.Health.Dicom.Core/Features/Update/UpdateInstanceOperationService.cs +++ b/src/Microsoft.Health.Dicom.Core/Features/Update/UpdateInstanceOperationService.cs @@ -15,6 +15,7 @@ using Microsoft.Extensions.Options; using Microsoft.Health.Dicom.Core.Exceptions; using Microsoft.Health.Dicom.Core.Extensions; +using Microsoft.Health.Dicom.Core.Features.Audit; using Microsoft.Health.Dicom.Core.Features.Common; using Microsoft.Health.Dicom.Core.Features.Context; using Microsoft.Health.Dicom.Core.Features.Diagnostic; @@ -103,7 +104,7 @@ public async Task QueueUpdateOperationAsync( var operation = await _client.StartUpdateOperationAsync(operationId, updateSpecification, partition, cancellationToken); string input = JsonSerializer.Serialize(updateSpecification, _jsonSerializerOptions.Value); - _telemetryClient.ForwardOperationLogTrace("Dicom update operation started successfully.", operationId.ToString(), input); + _telemetryClient.ForwardOperationLogTrace("Dicom update operation started successfully.", operationId.ToString(), input, AuditEventSubType.UpdateStudyOperation); return new UpdateInstanceResponse(operation); } catch (Exception ex) diff --git a/src/Microsoft.Health.Dicom.Functions.UnitTests/Update/UpdateDurableFunctionTests.cs b/src/Microsoft.Health.Dicom.Functions.UnitTests/Update/UpdateDurableFunctionTests.cs index c0381541be..b3f1a183b1 100644 --- a/src/Microsoft.Health.Dicom.Functions.UnitTests/Update/UpdateDurableFunctionTests.cs +++ b/src/Microsoft.Health.Dicom.Functions.UnitTests/Update/UpdateDurableFunctionTests.cs @@ -11,6 +11,7 @@ using Microsoft.ApplicationInsights.Extensibility; using Microsoft.Extensions.Options; using Microsoft.Health.Dicom.Core.Configs; +using Microsoft.Health.Dicom.Core.Features.Audit; using Microsoft.Health.Dicom.Core.Features.Common; using Microsoft.Health.Dicom.Core.Features.ExtendedQueryTag; using Microsoft.Health.Dicom.Core.Features.Retrieve; @@ -68,6 +69,7 @@ public UpdateDurableFunctionTests() Substitute.For(), _updateMeter, telemetryClient, + Substitute.For(), Options.Create(_jsonSerializerOptions), Options.Create(new FeatureConfiguration())); _updateDurableFunctionWithExternalStore = new UpdateDurableFunction( @@ -80,6 +82,7 @@ public UpdateDurableFunctionTests() Substitute.For(), _updateMeter, telemetryClient, + Substitute.For(), Options.Create(_jsonSerializerOptions), Options.Create(new FeatureConfiguration { EnableExternalStore = true, })); InitializeMetricExporter(); diff --git a/src/Microsoft.Health.Dicom.Functions/Registration/ServiceCollectionExtensions.cs b/src/Microsoft.Health.Dicom.Functions/Registration/ServiceCollectionExtensions.cs index c04755bbf0..cf55e5f36d 100644 --- a/src/Microsoft.Health.Dicom.Functions/Registration/ServiceCollectionExtensions.cs +++ b/src/Microsoft.Health.Dicom.Functions/Registration/ServiceCollectionExtensions.cs @@ -14,6 +14,7 @@ using Microsoft.Extensions.DependencyInjection.Extensions; using Microsoft.Health.Dicom.Core.Configs; using Microsoft.Health.Dicom.Core.Extensions; +using Microsoft.Health.Dicom.Core.Features.Audit; using Microsoft.Health.Dicom.Core.Features.FellowOakDicom; using Microsoft.Health.Dicom.Core.Features.Telemetry; using Microsoft.Health.Dicom.Core.Modules; @@ -66,7 +67,8 @@ public static IDicomFunctionsBuilder ConfigureFunctions( .AddFunctionsOptions(configuration, UpdateOptions.SectionName) .ConfigureDurableFunctionSerialization() .AddJsonSerializerOptions(o => o.ConfigureDefaultDicomSettings()) - .AddSingleton()); + .AddSingleton() + .AddSingleton()); } /// diff --git a/src/Microsoft.Health.Dicom.Functions/Update/UpdateDurableFunction.Orchestration.cs b/src/Microsoft.Health.Dicom.Functions/Update/UpdateDurableFunction.Orchestration.cs index 72616ef278..5bce1186f2 100644 --- a/src/Microsoft.Health.Dicom.Functions/Update/UpdateDurableFunction.Orchestration.cs +++ b/src/Microsoft.Health.Dicom.Functions/Update/UpdateDurableFunction.Orchestration.cs @@ -6,13 +6,17 @@ using System; using System.Collections.Generic; using System.Data; +using System.Diagnostics; using System.Linq; +using System.Net; using System.Text.Json; using System.Threading.Tasks; using EnsureThat; using Microsoft.Azure.WebJobs; using Microsoft.Azure.WebJobs.Extensions.DurableTask; using Microsoft.Extensions.Logging; +using Microsoft.Health.Core.Features.Audit; +using Microsoft.Health.Dicom.Core.Features.Audit; using Microsoft.Health.Dicom.Core.Features.Diagnostic; using Microsoft.Health.Dicom.Core.Features.Model; using Microsoft.Health.Dicom.Core.Features.Partitioning; @@ -50,6 +54,16 @@ public async Task UpdateInstancesV5Async( UpdateCheckpoint input = context.GetInput(); input.Partition ??= new Partition(input.PartitionKey, Partition.UnknownName); + _auditLogger.LogAudit( + AuditAction.Executing, + AuditEventSubType.UpdateStudyOperation, + null, + null, + Activity.Current?.RootId, + null, + null, + null); + if (input.NumberOfStudyCompleted < input.TotalNumberOfStudies) { string studyInstanceUid = input.StudyInstanceUids[input.NumberOfStudyCompleted]; @@ -156,7 +170,22 @@ await context.CallActivityWithRetryAsync( input.NumberOfStudyFailed, input.TotalNumberOfInstanceUpdated); - _telemetryClient.ForwardOperationLogTrace("Update operation completed with errors", context.InstanceId, serializedInput); + _telemetryClient.ForwardOperationLogTrace( + "Update operation completed with errors", + context.InstanceId, + serializedInput, + AuditEventSubType.UpdateStudyOperation, + ApplicationInsights.DataContracts.SeverityLevel.Error); + + _auditLogger.LogAudit( + AuditAction.Executed, + AuditEventSubType.UpdateStudyOperation, + null, + HttpStatusCode.BadRequest, + Activity.Current?.RootId, + null, + null, + null); // Throwing the exception so that it can set the operation status to Failed throw new OperationErrorException("Update operation completed with errors."); @@ -167,7 +196,17 @@ await context.CallActivityWithRetryAsync( input.NumberOfStudyCompleted, input.TotalNumberOfInstanceUpdated); - _telemetryClient.ForwardOperationLogTrace("Update operation completed successfully", context.InstanceId, serializedInput); + _telemetryClient.ForwardOperationLogTrace("Update operation completed successfully", context.InstanceId, serializedInput, AuditEventSubType.UpdateStudyOperation); + + _auditLogger.LogAudit( + AuditAction.Executed, + AuditEventSubType.UpdateStudyOperation, + null, + HttpStatusCode.OK, + Activity.Current?.RootId, + null, + null, + null); } } } @@ -201,7 +240,7 @@ private async Task HandleException( foreach (string error in instanceErrors) { - _telemetryClient.ForwardOperationLogTrace(error, context.InstanceId, string.Empty); + _telemetryClient.ForwardOperationLogTrace(error, context.InstanceId, string.Empty, AuditEventSubType.UpdateStudyOperation, ApplicationInsights.DataContracts.SeverityLevel.Error); } } diff --git a/src/Microsoft.Health.Dicom.Functions/Update/UpdateDurableFunction.cs b/src/Microsoft.Health.Dicom.Functions/Update/UpdateDurableFunction.cs index 8ca27ad6a9..ea0014f9a9 100644 --- a/src/Microsoft.Health.Dicom.Functions/Update/UpdateDurableFunction.cs +++ b/src/Microsoft.Health.Dicom.Functions/Update/UpdateDurableFunction.cs @@ -8,6 +8,7 @@ using Microsoft.ApplicationInsights; using Microsoft.Extensions.Options; using Microsoft.Health.Dicom.Core.Configs; +using Microsoft.Health.Dicom.Core.Features.Audit; using Microsoft.Health.Dicom.Core.Features.Common; using Microsoft.Health.Dicom.Core.Features.ExtendedQueryTag; using Microsoft.Health.Dicom.Core.Features.Retrieve; @@ -31,6 +32,7 @@ public partial class UpdateDurableFunction private readonly IQueryTagService _queryTagService; private readonly UpdateMeter _updateMeter; private readonly TelemetryClient _telemetryClient; + private readonly IAuditLogger _auditLogger; private readonly JsonSerializerOptions _jsonSerializerOptions; private readonly bool _externalStoreEnabled; @@ -44,6 +46,7 @@ public UpdateDurableFunction( IQueryTagService queryTagService, UpdateMeter updateMeter, TelemetryClient telemetryClient, + IAuditLogger auditLogger, IOptions jsonSerializerOptions, IOptions featureConfiguration) { @@ -57,6 +60,7 @@ public UpdateDurableFunction( _jsonSerializerOptions = EnsureArg.IsNotNull(jsonSerializerOptions?.Value, nameof(jsonSerializerOptions)); _updateMeter = EnsureArg.IsNotNull(updateMeter, nameof(updateMeter)); _telemetryClient = EnsureArg.IsNotNull(telemetryClient, nameof(telemetryClient)); + _auditLogger = EnsureArg.IsNotNull(auditLogger, nameof(auditLogger)); _options = EnsureArg.IsNotNull(configOptions?.Value, nameof(configOptions)); _externalStoreEnabled = featureConfiguration.Value.EnableExternalStore; }