Skip to content

Commit

Permalink
Pass correct severity level for shoeboxlogs (#3249)
Browse files Browse the repository at this point in the history
* 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
  • Loading branch information
bcarthic authored Dec 8, 2023
1 parent 621abb4 commit 384d661
Show file tree
Hide file tree
Showing 10 changed files with 97 additions and 26 deletions.
Original file line number Diff line number Diff line change
Expand Up @@ -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",
Expand Down
Original file line number Diff line number Diff line change
@@ -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.
// -------------------------------------------------------------------------------------------------
Expand Down Expand Up @@ -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
}

Expand All @@ -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
}

Expand All @@ -175,4 +178,4 @@ private static (TelemetryClient, MockTelemetryChannel) CreateTelemetryClientWith

return (new TelemetryClient(configuration), channel);
}
}
}
Original file line number Diff line number Diff line change
Expand Up @@ -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";
}
Original file line number Diff line number Diff line change
Expand Up @@ -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";
Expand All @@ -36,16 +37,18 @@ internal static class LogForwarderExtensions
/// <param name="telemetryClient">client to use to emit the trace</param>
/// <param name="message">message to set on the trace log</param>
/// <param name="instanceIdentifier">identifier to use to set UIDs on log and telemetry properties</param>
/// <param name="severityLevel">Severity level of the message</param>
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);
Expand All @@ -64,14 +67,16 @@ public static void ForwardLogTrace(
/// <remarks>NOTE - do not use this if reporting on any specific instance. Only use as high level remarks. Attempt to use identifiers wherever possible</remarks>
/// <param name="telemetryClient">client to use to emit the trace</param>
/// <param name="message">message to set on the trace log</param>
/// <param name="severityLevel">Severity level of the message</param>
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);
Expand All @@ -84,18 +89,20 @@ public static void ForwardLogTrace(
/// <param name="message">message to set on the trace log</param>
/// <param name="partition">Partition within which file is residing</param>
/// <param name="fileProperties">File properties of file this message is regarding</param>
/// <param name="severityLevel">Severity level of the message</param>
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);
Expand All @@ -109,26 +116,32 @@ public static void ForwardLogTrace(

/// <summary>
/// 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.
/// </summary>
/// <param name="telemetryClient">client to use to emit the trace</param>
/// <param name="message">message to set on the trace log</param>
/// <param name="operationId">operation id</param>
/// <param name="input">Input payload to pass to the forward logger</param>
/// <param name="operationName">Operation name of the trace event</param>
/// <param name="severityLevel">Severity level of the message</param>
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;
}
}
Expand All @@ -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);
}
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -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);
}
}
}
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand Down Expand Up @@ -103,7 +104,7 @@ public async Task<UpdateInstanceResponse> 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)
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand Down Expand Up @@ -68,6 +69,7 @@ public UpdateDurableFunctionTests()
Substitute.For<IQueryTagService>(),
_updateMeter,
telemetryClient,
Substitute.For<IAuditLogger>(),
Options.Create(_jsonSerializerOptions),
Options.Create(new FeatureConfiguration()));
_updateDurableFunctionWithExternalStore = new UpdateDurableFunction(
Expand All @@ -80,6 +82,7 @@ public UpdateDurableFunctionTests()
Substitute.For<IQueryTagService>(),
_updateMeter,
telemetryClient,
Substitute.For<IAuditLogger>(),
Options.Create(_jsonSerializerOptions),
Options.Create(new FeatureConfiguration { EnableExternalStore = true, }));
InitializeMetricExporter();
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand Down Expand Up @@ -66,7 +67,8 @@ public static IDicomFunctionsBuilder ConfigureFunctions(
.AddFunctionsOptions<UpdateOptions>(configuration, UpdateOptions.SectionName)
.ConfigureDurableFunctionSerialization()
.AddJsonSerializerOptions(o => o.ConfigureDefaultDicomSettings())
.AddSingleton<UpdateMeter>());
.AddSingleton<UpdateMeter>()
.AddSingleton<IAuditLogger, AuditLogger>());
}

/// <summary>
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand Down Expand Up @@ -50,6 +54,16 @@ public async Task UpdateInstancesV5Async(
UpdateCheckpoint input = context.GetInput<UpdateCheckpoint>();
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];
Expand Down Expand Up @@ -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.");
Expand All @@ -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);
}
}
}
Expand Down Expand Up @@ -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);
}
}

Expand Down
Loading

0 comments on commit 384d661

Please sign in to comment.