From 57f11c609d7f12830a8bd91688cfdb1e9e775d9e Mon Sep 17 00:00:00 2001 From: Chris Gillum <cgillum@microsoft.com> Date: Wed, 24 Aug 2022 16:29:19 -0700 Subject: [PATCH 1/3] Enable redacting user-code exception messages --- src/DurableTask.Core/Common/Utils.cs | 48 +++++++++++++----- src/DurableTask.Core/Logging/LogEvents.cs | 4 +- src/DurableTask.Core/Logging/LogHelper.cs | 59 ++++++++++++++++++++--- 3 files changed, 90 insertions(+), 21 deletions(-) diff --git a/src/DurableTask.Core/Common/Utils.cs b/src/DurableTask.Core/Common/Utils.cs index e2ea77dcd..7c3cd760a 100644 --- a/src/DurableTask.Core/Common/Utils.cs +++ b/src/DurableTask.Core/Common/Utils.cs @@ -10,13 +10,12 @@ // See the License for the specific language governing permissions and // limitations under the License. // ---------------------------------------------------------------------------------- - +#nullable enable namespace DurableTask.Core.Common { using System; using System.Collections.Generic; using System.Diagnostics; - using System.Dynamic; using System.IO; using System.IO.Compression; using System.Linq; @@ -75,6 +74,31 @@ public static class Utils Environment.GetEnvironmentVariable("DTFX_APP_NAME") ?? string.Empty; + /// <summary> + /// Gets or sets a value indicating whether to redact user code exceptions from log output. + /// </summary> + /// <remarks> + /// This value defaults to <c>true</c> if the WEBSITE_SITE_NAME is set to a non-empty value, which is always + /// the case in hosted Azure environments where log telemetry is automatically captured. This value can be also + /// be set explicitly by assigning the DTFX_REDACT_USER_CODE_EXCEPTIONS environment variable to "1" or "true". + /// </remarks> + public static bool RedactUserCodeExceptions { get; set; } = GetRedactUserCodeExceptionsDefaultValue(); + + static bool GetRedactUserCodeExceptionsDefaultValue() + { + string? configuredValue = Environment.GetEnvironmentVariable("DTFX_REDACT_USER_CODE_EXCEPTIONS")?.Trim(); + if (configuredValue != null) + { + return configuredValue == "1" || configuredValue.Equals("true", StringComparison.OrdinalIgnoreCase); + } + else + { + // Fallback case when DTFX_REDACT_USER_CODE_EXCEPTIONS is not defined is to automatically redact + // any time we appear to be in a hosted Azure environment. + return Environment.GetEnvironmentVariable("WEBSITE_SITE_NAME") != null; + } + } + /// <summary> /// NoOp utility method /// </summary> @@ -139,7 +163,7 @@ public static Stream WriteStringToStream(string input, bool compress, out long o if (compress) { - Stream compressedStream = GetCompressedStream(resultStream); + Stream compressedStream = GetCompressedStream(resultStream)!; resultStream.Dispose(); resultStream = compressedStream; } @@ -212,7 +236,7 @@ public static bool IsGzipStream(Stream stream) /// </summary> /// <param name="input"></param> /// <returns></returns> - public static Stream GetCompressedStream(Stream input) + public static Stream? GetCompressedStream(Stream input) { if (input == null) { @@ -236,7 +260,7 @@ public static Stream GetCompressedStream(Stream input) /// </summary> /// <param name="input"></param> /// <returns></returns> - public static async Task<Stream> GetDecompressedStreamAsync(Stream input) + public static async Task<Stream?> GetDecompressedStreamAsync(Stream input) { if (input == null) { @@ -294,7 +318,7 @@ public static async Task ExecuteWithRetries(Func<Task> retryAction, string sessi } int retryCount = numberOfAttempts; - ExceptionDispatchInfo lastException = null; + ExceptionDispatchInfo? lastException = null; while (retryCount-- > 0) { try @@ -322,7 +346,7 @@ public static async Task ExecuteWithRetries(Func<Task> retryAction, string sessi /// <summary> /// Executes the supplied action until successful or the supplied number of attempts is reached /// </summary> - public static async Task<T> ExecuteWithRetries<T>(Func<Task<T>> retryAction, string sessionId, string operation, + public static async Task<T?> ExecuteWithRetries<T>(Func<Task<T>> retryAction, string sessionId, string operation, int numberOfAttempts, int delayInAttemptsSecs) { if (numberOfAttempts == 0) @@ -332,7 +356,7 @@ public static async Task<T> ExecuteWithRetries<T>(Func<Task<T>> retryAction, str } int retryCount = numberOfAttempts; - ExceptionDispatchInfo lastException = null; + ExceptionDispatchInfo? lastException = null; while (retryCount-- > 0) { try @@ -394,14 +418,14 @@ public static string SerializeCause(Exception originalException, DataConverter c /// <summary> /// Retrieves the exception from a previously serialized exception /// </summary> - public static Exception RetrieveCause(string details, DataConverter converter) + public static Exception? RetrieveCause(string details, DataConverter converter) { if (converter == null) { throw new ArgumentNullException(nameof(converter)); } - Exception cause = null; + Exception? cause = null; try { if (!string.IsNullOrWhiteSpace(details)) @@ -600,9 +624,9 @@ internal static Type ConvertFromGenericType(Type[] genericParameters, Type[] gen internal sealed class TypeMetadata { - public string AssemblyName { get; set; } + public string? AssemblyName { get; set; } - public string FullyQualifiedTypeName { get; set; } + public string? FullyQualifiedTypeName { get; set; } } } } diff --git a/src/DurableTask.Core/Logging/LogEvents.cs b/src/DurableTask.Core/Logging/LogEvents.cs index c819aea68..d48d9a36d 100644 --- a/src/DurableTask.Core/Logging/LogEvents.cs +++ b/src/DurableTask.Core/Logging/LogEvents.cs @@ -1279,13 +1279,13 @@ public TaskActivityFailure( OrchestrationInstance instance, string name, TaskFailedEvent taskEvent, - Exception exception) + string exceptionDetails) { this.InstanceId = instance.InstanceId; this.ExecutionId = instance.ExecutionId; this.Name = name; this.TaskEventId = taskEvent.EventId; - this.Details = exception.ToString(); + this.Details = exceptionDetails; } [StructuredLogField] diff --git a/src/DurableTask.Core/Logging/LogHelper.cs b/src/DurableTask.Core/Logging/LogHelper.cs index 73aaf6cb0..fbe3d41a6 100644 --- a/src/DurableTask.Core/Logging/LogHelper.cs +++ b/src/DurableTask.Core/Logging/LogHelper.cs @@ -10,20 +10,22 @@ // See the License for the specific language governing permissions and // limitations under the License. // ---------------------------------------------------------------------------------- - +#nullable enable namespace DurableTask.Core.Logging { using System; using System.Collections.Generic; + using System.Text; using DurableTask.Core.Command; + using DurableTask.Core.Common; using DurableTask.Core.History; using Microsoft.Extensions.Logging; class LogHelper { - readonly ILogger log; + readonly ILogger? log; - public LogHelper(ILogger log) + public LogHelper(ILogger? log) { // null is okay this.log = log; @@ -93,7 +95,6 @@ internal void DispatcherStarting(WorkItemDispatcherContext context) } } - /// <summary> /// Logs that a work item dispatcher has stopped running. /// </summary> @@ -360,7 +361,7 @@ internal void WaitingForInstance(OrchestrationInstance instance, TimeSpan timeou /// </summary> /// <param name="instanceId">The ID of the instance.</param> /// <param name="executionId">The execution ID of the instance, if applicable.</param> - internal void FetchingInstanceState(string instanceId, string executionId = null) + internal void FetchingInstanceState(string instanceId, string? executionId = null) { if (this.IsStructuredLoggingEnabled) { @@ -567,8 +568,11 @@ internal void TaskActivityFailure( { if (this.IsStructuredLoggingEnabled) { + // This is a user-code exception which could contain sensitive information. Depending on the + // environment, some of the exception details may need to be redacted. + string exceptionDetails = GetSafeExceptionDetails(exception); this.WriteStructuredLog( - new LogEvents.TaskActivityFailure(instance, name, failedEvent, exception), + new LogEvents.TaskActivityFailure(instance, name, failedEvent, exceptionDetails), exception); } } @@ -639,9 +643,50 @@ internal void RenewActivityMessageFailed(TaskActivityWorkItem workItem, Exceptio } #endregion - void WriteStructuredLog(ILogEvent logEvent, Exception exception = null) + void WriteStructuredLog(ILogEvent logEvent, Exception? exception = null) { this.log?.LogDurableEvent(logEvent, exception); } + + static string GetSafeExceptionDetails(Exception? exception) + { + if (exception == null) + { + return string.Empty; + } + + if (Utils.RedactUserCodeExceptions) + { + // Redact the exception message since its possible to contain sensitive information (PII, secrets, etc.) + // Exception.ToString() code: https://referencesource.microsoft.com/#mscorlib/system/exception.cs,e2e19f4ed8da81aa + // Example output for a method chain of Foo() --> Bar() --> Baz() --> (exception): + // System.ApplicationException: [Redacted] + // ---> System.Exception: [Redacted] + // ---> System.InvalidOperationException: [Redacted] + // at UserQuery.<Main>g__Baz|4_3() in C:\Users\xxx\AppData\Local\Temp\LINQPad7\_wrmpjfpn\hjvskp\LINQPadQuery:line 68 + // at UserQuery.<Main>g__Bar|4_2() in C:\Users\xxx\AppData\Local\Temp\LINQPad7\_wrmpjfpn\hjvskp\LINQPadQuery:line 58 + // --- End of inner exception stack trace --- + // at UserQuery.<Main>g__Bar|4_2() in C:\Users\xxx\AppData\Local\Temp\LINQPad7\_wrmpjfpn\hjvskp\LINQPadQuery:line 62 + // at UserQuery.<Main>g__Foo|4_1() in C:\Users\xxx\AppData\Local\Temp\LINQPad7\_wrmpjfpn\hjvskp\LINQPadQuery:line 46 + // --- End of inner exception stack trace --- + // at UserQuery.<Main>g__Foo|4_1() in C:\Users\xxx\AppData\Local\Temp\LINQPad7\_wrmpjfpn\hjvskp\LINQPadQuery:line 50 + // at UserQuery.Main() in C:\Users\xxx\AppData\Local\Temp\LINQPad7\_wrmpjfpn\hjvskp\LINQPadQuery:line 4 + var sb = new StringBuilder(capacity: 1024); + sb.Append(exception.GetType().FullName).Append(": ").Append("[Redacted]"); + if (exception.InnerException != null) + { + // Recursive + sb.AppendLine().Append(" ---> ").AppendLine(GetSafeExceptionDetails(exception.InnerException)); + sb.Append(" --- End of inner exception stack trace ---"); + } + + sb.AppendLine().Append(exception.StackTrace); + return sb.ToString(); + } + else + { + return exception.ToString(); + } + } } } From 0338ba407dd7dc110b4738ff4a35d7b9286a5f91 Mon Sep 17 00:00:00 2001 From: Chris Gillum <cgillum@microsoft.com> Date: Wed, 24 Aug 2022 16:55:17 -0700 Subject: [PATCH 2/3] Fix new nullable check build errors --- src/DurableTask.Core/TaskActivityDispatcher.cs | 4 ++-- src/DurableTask.Core/TaskOrchestrationDispatcher.cs | 10 +++++----- src/DurableTask.Core/TaskOrchestrationExecutor.cs | 2 +- 3 files changed, 8 insertions(+), 8 deletions(-) diff --git a/src/DurableTask.Core/TaskActivityDispatcher.cs b/src/DurableTask.Core/TaskActivityDispatcher.cs index c0429b0df..9c83fccce 100644 --- a/src/DurableTask.Core/TaskActivityDispatcher.cs +++ b/src/DurableTask.Core/TaskActivityDispatcher.cs @@ -102,7 +102,7 @@ async Task OnProcessWorkItemAsync(TaskActivityWorkItem workItem) Activity? diagnosticActivity = null; try { - if (string.IsNullOrWhiteSpace(orchestrationInstance?.InstanceId)) + if (orchestrationInstance == null || string.IsNullOrWhiteSpace(orchestrationInstance.InstanceId)) { this.logHelper.TaskActivityDispatcherError( workItem, @@ -242,7 +242,7 @@ await this.dispatchPipeline.RunAsync(dispatchContext, async _ => catch (SessionAbortedException e) { // The activity aborted its execution - this.logHelper.TaskActivityAborted(orchestrationInstance, scheduledEvent, e.Message); + this.logHelper.TaskActivityAborted(orchestrationInstance, scheduledEvent!, e.Message); TraceHelper.TraceInstance(TraceEventType.Warning, "TaskActivityDispatcher-ExecutionAborted", orchestrationInstance, "{0}: {1}", scheduledEvent?.Name, e.Message); await this.orchestrationService.AbandonTaskActivityWorkItemAsync(workItem); } diff --git a/src/DurableTask.Core/TaskOrchestrationDispatcher.cs b/src/DurableTask.Core/TaskOrchestrationDispatcher.cs index 867cebaf5..11f6bf75c 100644 --- a/src/DurableTask.Core/TaskOrchestrationDispatcher.cs +++ b/src/DurableTask.Core/TaskOrchestrationDispatcher.cs @@ -323,7 +323,7 @@ protected async Task<bool> OnProcessWorkItemAsync(TaskOrchestrationWorkItem work continuedAsNew = false; continuedAsNewMessage = null; - this.logHelper.OrchestrationExecuting(runtimeState.OrchestrationInstance, runtimeState.Name); + this.logHelper.OrchestrationExecuting(runtimeState.OrchestrationInstance!, runtimeState.Name); TraceHelper.TraceInstance( TraceEventType.Verbose, "TaskOrchestrationDispatcher-ExecuteUserOrchestration-Begin", @@ -343,7 +343,7 @@ protected async Task<bool> OnProcessWorkItemAsync(TaskOrchestrationWorkItem work IReadOnlyList<OrchestratorAction> decisions = workItem.Cursor.LatestDecisions.ToList(); this.logHelper.OrchestrationExecuted( - runtimeState.OrchestrationInstance, + runtimeState.OrchestrationInstance!, runtimeState.Name, decisions); TraceHelper.TraceInstance( @@ -846,7 +846,7 @@ TaskMessage ProcessScheduleTaskDecision( } this.logHelper.SchedulingActivity( - runtimeState.OrchestrationInstance, + runtimeState.OrchestrationInstance!, scheduledEvent); runtimeState.AddEvent(scheduledEvent); @@ -874,7 +874,7 @@ TaskMessage ProcessCreateTimerDecision( }; this.logHelper.CreatingTimer( - runtimeState.OrchestrationInstance, + runtimeState.OrchestrationInstance!, timerCreatedEvent, isInternal); @@ -943,7 +943,7 @@ TaskMessage ProcessSendEventDecision( runtimeState.AddEvent(historyEvent); - this.logHelper.RaisingEvent(runtimeState.OrchestrationInstance, historyEvent); + this.logHelper.RaisingEvent(runtimeState.OrchestrationInstance!, historyEvent); return new TaskMessage { diff --git a/src/DurableTask.Core/TaskOrchestrationExecutor.cs b/src/DurableTask.Core/TaskOrchestrationExecutor.cs index 9320db5de..b0ca99976 100644 --- a/src/DurableTask.Core/TaskOrchestrationExecutor.cs +++ b/src/DurableTask.Core/TaskOrchestrationExecutor.cs @@ -139,7 +139,7 @@ void ProcessEvents(IEnumerable<HistoryEvent> events) Exception? exception = this.result.Exception?.InnerExceptions.FirstOrDefault(); Debug.Assert(exception != null); - if (Utils.IsExecutionAborting(exception)) + if (Utils.IsExecutionAborting(exception!)) { // Let this exception propagate out to be handled by the dispatcher ExceptionDispatchInfo.Capture(exception).Throw(); From bcb7c389c8a99f4f0594148609731fb2a5b37b26 Mon Sep 17 00:00:00 2001 From: Chris Gillum <cgillum@microsoft.com> Date: Wed, 14 Sep 2022 13:34:43 -0700 Subject: [PATCH 3/3] Merge with main + PR feedback + narrower scope --- src/DurableTask.Core/Logging/LogEvents.cs | 9 ++-- src/DurableTask.Core/Logging/LogHelper.cs | 64 ++++++++++------------- 2 files changed, 33 insertions(+), 40 deletions(-) diff --git a/src/DurableTask.Core/Logging/LogEvents.cs b/src/DurableTask.Core/Logging/LogEvents.cs index d48d9a36d..d34cc5fcb 100644 --- a/src/DurableTask.Core/Logging/LogEvents.cs +++ b/src/DurableTask.Core/Logging/LogEvents.cs @@ -1275,17 +1275,20 @@ void IEventSourceEvent.WriteEventSource() => internal class TaskActivityFailure : StructuredLogEvent, IEventSourceEvent { + readonly Exception exception; + public TaskActivityFailure( OrchestrationInstance instance, string name, TaskFailedEvent taskEvent, - string exceptionDetails) + Exception exception) { this.InstanceId = instance.InstanceId; this.ExecutionId = instance.ExecutionId; this.Name = name; this.TaskEventId = taskEvent.EventId; - this.Details = exceptionDetails; + this.Details = exception.ToString(); + this.exception = exception; } [StructuredLogField] @@ -1318,7 +1321,7 @@ void IEventSourceEvent.WriteEventSource() => this.ExecutionId, this.Name, this.TaskEventId, - this.Details, + Utils.RedactUserCodeExceptions ? LogHelper.GetRedactedExceptionDetails(this.exception) : this.Details, // We have to be extra guarded about logging user exceptions to EventSource (ETW) Utils.AppName, Utils.PackageVersion); } diff --git a/src/DurableTask.Core/Logging/LogHelper.cs b/src/DurableTask.Core/Logging/LogHelper.cs index fbe3d41a6..30615360f 100644 --- a/src/DurableTask.Core/Logging/LogHelper.cs +++ b/src/DurableTask.Core/Logging/LogHelper.cs @@ -568,11 +568,8 @@ internal void TaskActivityFailure( { if (this.IsStructuredLoggingEnabled) { - // This is a user-code exception which could contain sensitive information. Depending on the - // environment, some of the exception details may need to be redacted. - string exceptionDetails = GetSafeExceptionDetails(exception); this.WriteStructuredLog( - new LogEvents.TaskActivityFailure(instance, name, failedEvent, exceptionDetails), + new LogEvents.TaskActivityFailure(instance, name, failedEvent, exception), exception); } } @@ -648,45 +645,38 @@ void WriteStructuredLog(ILogEvent logEvent, Exception? exception = null) this.log?.LogDurableEvent(logEvent, exception); } - static string GetSafeExceptionDetails(Exception? exception) + internal static string GetRedactedExceptionDetails(Exception? exception) { if (exception == null) { return string.Empty; } - if (Utils.RedactUserCodeExceptions) - { - // Redact the exception message since its possible to contain sensitive information (PII, secrets, etc.) - // Exception.ToString() code: https://referencesource.microsoft.com/#mscorlib/system/exception.cs,e2e19f4ed8da81aa - // Example output for a method chain of Foo() --> Bar() --> Baz() --> (exception): - // System.ApplicationException: [Redacted] - // ---> System.Exception: [Redacted] - // ---> System.InvalidOperationException: [Redacted] - // at UserQuery.<Main>g__Baz|4_3() in C:\Users\xxx\AppData\Local\Temp\LINQPad7\_wrmpjfpn\hjvskp\LINQPadQuery:line 68 - // at UserQuery.<Main>g__Bar|4_2() in C:\Users\xxx\AppData\Local\Temp\LINQPad7\_wrmpjfpn\hjvskp\LINQPadQuery:line 58 - // --- End of inner exception stack trace --- - // at UserQuery.<Main>g__Bar|4_2() in C:\Users\xxx\AppData\Local\Temp\LINQPad7\_wrmpjfpn\hjvskp\LINQPadQuery:line 62 - // at UserQuery.<Main>g__Foo|4_1() in C:\Users\xxx\AppData\Local\Temp\LINQPad7\_wrmpjfpn\hjvskp\LINQPadQuery:line 46 - // --- End of inner exception stack trace --- - // at UserQuery.<Main>g__Foo|4_1() in C:\Users\xxx\AppData\Local\Temp\LINQPad7\_wrmpjfpn\hjvskp\LINQPadQuery:line 50 - // at UserQuery.Main() in C:\Users\xxx\AppData\Local\Temp\LINQPad7\_wrmpjfpn\hjvskp\LINQPadQuery:line 4 - var sb = new StringBuilder(capacity: 1024); - sb.Append(exception.GetType().FullName).Append(": ").Append("[Redacted]"); - if (exception.InnerException != null) - { - // Recursive - sb.AppendLine().Append(" ---> ").AppendLine(GetSafeExceptionDetails(exception.InnerException)); - sb.Append(" --- End of inner exception stack trace ---"); - } - - sb.AppendLine().Append(exception.StackTrace); - return sb.ToString(); - } - else - { - return exception.ToString(); - } + // Redact the exception message since its possible to contain sensitive information (PII, secrets, etc.) + // Exception.ToString() code: https://referencesource.microsoft.com/#mscorlib/system/exception.cs,e2e19f4ed8da81aa + // Example output for a method chain of Foo() --> Bar() --> Baz() --> (exception): + // System.ApplicationException: [Redacted] + // ---> System.Exception: [Redacted] + // ---> System.InvalidOperationException: [Redacted] + // at UserQuery.<Main>g__Baz|4_3() in C:\Users\xxx\AppData\Local\Temp\LINQPad7\_wrmpjfpn\hjvskp\LINQPadQuery:line 68 + // at UserQuery.<Main>g__Bar|4_2() in C:\Users\xxx\AppData\Local\Temp\LINQPad7\_wrmpjfpn\hjvskp\LINQPadQuery:line 58 + // --- End of inner exception stack trace --- + // at UserQuery.<Main>g__Bar|4_2() in C:\Users\xxx\AppData\Local\Temp\LINQPad7\_wrmpjfpn\hjvskp\LINQPadQuery:line 62 + // at UserQuery.<Main>g__Foo|4_1() in C:\Users\xxx\AppData\Local\Temp\LINQPad7\_wrmpjfpn\hjvskp\LINQPadQuery:line 46 + // --- End of inner exception stack trace --- + // at UserQuery.<Main>g__Foo|4_1() in C:\Users\xxx\AppData\Local\Temp\LINQPad7\_wrmpjfpn\hjvskp\LINQPadQuery:line 50 + // at UserQuery.Main() in C:\Users\xxx\AppData\Local\Temp\LINQPad7\_wrmpjfpn\hjvskp\LINQPadQuery:line 4 + var sb = new StringBuilder(capacity: 1024); + sb.Append(exception.GetType().FullName).Append(": ").Append("[Redacted]"); + if (exception.InnerException != null) + { + // Recursive + sb.AppendLine().Append(" ---> ").AppendLine(GetRedactedExceptionDetails(exception.InnerException)); + sb.Append(" --- End of inner exception stack trace ---"); + } + + sb.AppendLine().Append(exception.StackTrace); + return sb.ToString(); } } }