Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Enable redacting user-code exception messages #790

Merged
merged 4 commits into from
Sep 14, 2022
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
48 changes: 36 additions & 12 deletions src/DurableTask.Core/Common/Utils.cs
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand Down Expand Up @@ -158,6 +157,31 @@ public static object DeserializeFromJson(JsonSerializer serializer, string jsonS
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>
Expand Down Expand Up @@ -223,7 +247,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;
}
Expand Down Expand Up @@ -295,7 +319,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)
{
Expand All @@ -319,7 +343,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)
{
Expand Down Expand Up @@ -377,7 +401,7 @@ public static async Task ExecuteWithRetries(Func<Task> retryAction, string sessi
}

int retryCount = numberOfAttempts;
ExceptionDispatchInfo lastException = null;
ExceptionDispatchInfo? lastException = null;
while (retryCount-- > 0)
{
try
Expand Down Expand Up @@ -405,7 +429,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)
Expand All @@ -415,7 +439,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
Expand Down Expand Up @@ -477,14 +501,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))
Expand Down Expand Up @@ -683,9 +707,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; }
}
}
}
5 changes: 4 additions & 1 deletion src/DurableTask.Core/Logging/LogEvents.cs
Original file line number Diff line number Diff line change
Expand Up @@ -1275,6 +1275,8 @@ void IEventSourceEvent.WriteEventSource() =>

internal class TaskActivityFailure : StructuredLogEvent, IEventSourceEvent
{
readonly Exception exception;

public TaskActivityFailure(
OrchestrationInstance instance,
string name,
Expand All @@ -1286,6 +1288,7 @@ public TaskActivityFailure(
this.Name = name;
this.TaskEventId = taskEvent.EventId;
this.Details = exception.ToString();
this.exception = exception;
}

[StructuredLogField]
Expand Down Expand Up @@ -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);
}
Expand Down
47 changes: 41 additions & 6 deletions src/DurableTask.Core/Logging/LogHelper.cs
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand Down Expand Up @@ -93,7 +95,6 @@ internal void DispatcherStarting(WorkItemDispatcherContext context)
}
}


/// <summary>
/// Logs that a work item dispatcher has stopped running.
/// </summary>
Expand Down Expand Up @@ -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)
{
Expand Down Expand Up @@ -639,9 +640,43 @@ 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);
}

internal static string GetRedactedExceptionDetails(Exception? exception)
{
if (exception == null)
cgillum marked this conversation as resolved.
Show resolved Hide resolved
{
return string.Empty;
}

// 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();
}
}
}
4 changes: 2 additions & 2 deletions src/DurableTask.Core/TaskActivityDispatcher.cs
Original file line number Diff line number Diff line change
Expand Up @@ -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,
Expand Down Expand Up @@ -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);
}
Expand Down
10 changes: 5 additions & 5 deletions src/DurableTask.Core/TaskOrchestrationDispatcher.cs
Original file line number Diff line number Diff line change
Expand Up @@ -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",
Expand All @@ -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(
Expand Down Expand Up @@ -852,7 +852,7 @@ TaskMessage ProcessScheduleTaskDecision(
}

this.logHelper.SchedulingActivity(
runtimeState.OrchestrationInstance,
runtimeState.OrchestrationInstance!,
scheduledEvent);

runtimeState.AddEvent(scheduledEvent);
Expand Down Expand Up @@ -880,7 +880,7 @@ TaskMessage ProcessCreateTimerDecision(
};

this.logHelper.CreatingTimer(
runtimeState.OrchestrationInstance,
runtimeState.OrchestrationInstance!,
timerCreatedEvent,
isInternal);

Expand Down Expand Up @@ -949,7 +949,7 @@ TaskMessage ProcessSendEventDecision(

runtimeState.AddEvent(historyEvent);

this.logHelper.RaisingEvent(runtimeState.OrchestrationInstance, historyEvent);
this.logHelper.RaisingEvent(runtimeState.OrchestrationInstance!, historyEvent);

return new TaskMessage
{
Expand Down
2 changes: 1 addition & 1 deletion src/DurableTask.Core/TaskOrchestrationExecutor.cs
Original file line number Diff line number Diff line change
Expand Up @@ -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();
Expand Down