From 94a1f2c98d4358f9d90e5383f333ac1e38b4df45 Mon Sep 17 00:00:00 2001 From: David Justo Date: Mon, 3 Jun 2024 17:50:39 -0700 Subject: [PATCH 01/30] first draft --- .../DurableEntityContext.cs | 16 +++-- .../DurableOrchestrationContext.cs | 4 +- .../RemoteOrchestratorContext.cs | 15 ++-- .../DurableTaskExtension.cs | 3 +- .../EndToEndTraceHelper.cs | 72 +++++++++---------- .../EtwEventSource.cs | 51 ++++++------- .../Listener/TaskActivityShim.cs | 2 +- .../Listener/TaskEntityShim.cs | 5 +- .../Listener/TaskOrchestrationShim.cs | 9 ++- .../OutOfProcMiddleware.cs | 15 ++-- 10 files changed, 91 insertions(+), 101 deletions(-) diff --git a/src/WebJobs.Extensions.DurableTask/ContextImplementations/DurableEntityContext.cs b/src/WebJobs.Extensions.DurableTask/ContextImplementations/DurableEntityContext.cs index 0b658eca5..228034dd3 100644 --- a/src/WebJobs.Extensions.DurableTask/ContextImplementations/DurableEntityContext.cs +++ b/src/WebJobs.Extensions.DurableTask/ContextImplementations/DurableEntityContext.cs @@ -122,13 +122,12 @@ bool IDurableEntityContext.HasState public void CaptureInternalError(Exception e, TaskEntityShim shim) { // first, try to get a quick ETW message out to help us diagnose what happened - string details = Utils.IsFatal(e) ? e.GetType().Name : e.ToString(); this.Config.TraceHelper.EntityBatchFailed( this.HubName, this.Name, this.InstanceId, shim.TraceFlags, - details); + e); // then, record the error for additional reporting and tracking in other places this.InternalError = ExceptionDispatchInfo.Capture(e); @@ -180,22 +179,27 @@ public void ThrowApplicationExceptionsIfAny() } } - public bool ErrorsPresent(out string description) + public bool ErrorsPresent(out string error, out string sanitizedError) { if (this.InternalError != null) { - description = $"Internal error: {this.InternalError.SourceException}"; + error = $"Internal error: {this.InternalError.SourceException}"; + sanitizedError = $"Internal error: {this.InternalError.SourceException.GetType().FullName} \n {this.InternalError.SourceException.StackTrace}"; return true; } else if (this.ApplicationErrors != null) { var messages = this.ApplicationErrors.Select(i => $"({i.SourceException.Message})"); - description = $"One or more operations failed: {string.Concat(messages)}"; + error = $"One or more operations failed: {string.Concat(messages)}"; + + string errorTypes = string.Join(", ", this.ApplicationErrors.Select(i => i.SourceException.GetType().FullName)); + sanitizedError = $"One or more operations failed: {errorTypes}"; return true; } else { - description = string.Empty; + error = string.Empty; + sanitizedError = string.Empty; return false; } } diff --git a/src/WebJobs.Extensions.DurableTask/ContextImplementations/DurableOrchestrationContext.cs b/src/WebJobs.Extensions.DurableTask/ContextImplementations/DurableOrchestrationContext.cs index 572c1b747..ff6c9f696 100644 --- a/src/WebJobs.Extensions.DurableTask/ContextImplementations/DurableOrchestrationContext.cs +++ b/src/WebJobs.Extensions.DurableTask/ContextImplementations/DurableOrchestrationContext.cs @@ -782,6 +782,7 @@ internal async Task CallDurableTaskFunctionAsync( operationName, input: "(replayed)", exception: "(replayed)", + sanitizedException: string.Empty, duration: 0, isReplay: true); } @@ -792,6 +793,7 @@ internal async Task CallDurableTaskFunctionAsync( functionName, this.InstanceId, reason: $"(replayed {exception.GetType().Name})", + sanitizedReason: string.Empty, functionType: functionType, isReplay: true); } @@ -933,7 +935,6 @@ internal void RaiseEvent(string name, string input) FunctionType.Orchestrator, this.InstanceId, name, - this.Config.GetIntputOutputTrace(responseMessage.Result), this.IsReplaying); } else @@ -943,7 +944,6 @@ internal void RaiseEvent(string name, string input) this.Name, this.InstanceId, name, - this.Config.GetIntputOutputTrace(input), this.IsReplaying); } diff --git a/src/WebJobs.Extensions.DurableTask/ContextImplementations/RemoteOrchestratorContext.cs b/src/WebJobs.Extensions.DurableTask/ContextImplementations/RemoteOrchestratorContext.cs index 5a8a50482..9c4d6a02e 100644 --- a/src/WebJobs.Extensions.DurableTask/ContextImplementations/RemoteOrchestratorContext.cs +++ b/src/WebJobs.Extensions.DurableTask/ContextImplementations/RemoteOrchestratorContext.cs @@ -64,18 +64,11 @@ internal OrchestratorExecutionResult GetResult() return this.executionResult ?? throw new InvalidOperationException($"The execution result has not yet been set using {nameof(this.SetResult)}."); } - internal bool TryGetOrchestrationErrorDetails(out string details) + internal bool TryGetOrchestrationErrorDetails(out Exception? failure) { - if (this.failure != null) - { - details = this.failure.Message; - return true; - } - else - { - details = string.Empty; - return false; - } + bool hasError = this.failure != null; + failure = hasError ? this.failure : null; + return hasError; } internal void SetResult(IEnumerable actions, string customStatus) diff --git a/src/WebJobs.Extensions.DurableTask/DurableTaskExtension.cs b/src/WebJobs.Extensions.DurableTask/DurableTaskExtension.cs index 3ae312bef..0af7dbbc3 100644 --- a/src/WebJobs.Extensions.DurableTask/DurableTaskExtension.cs +++ b/src/WebJobs.Extensions.DurableTask/DurableTaskExtension.cs @@ -1063,13 +1063,14 @@ private async Task EntityMiddleware(DispatchMiddlewareContext dispatchContext, F await next(); // 5. If there were internal or application errors, trace them for DF - if (entityContext.ErrorsPresent(out var description)) + if (entityContext.ErrorsPresent(out string description, out string sanitizedError)) { this.TraceHelper.FunctionFailed( entityContext.HubName, entityContext.Name, entityContext.InstanceId, description, + sanitizedReason: sanitizedError, functionType: FunctionType.Entity, isReplay: false); } diff --git a/src/WebJobs.Extensions.DurableTask/EndToEndTraceHelper.cs b/src/WebJobs.Extensions.DurableTask/EndToEndTraceHelper.cs index e730d6e71..9075e4c67 100644 --- a/src/WebJobs.Extensions.DurableTask/EndToEndTraceHelper.cs +++ b/src/WebJobs.Extensions.DurableTask/EndToEndTraceHelper.cs @@ -4,6 +4,7 @@ using System; using System.Diagnostics; using System.Net; +using DurableTask.Core.Common; using Microsoft.Extensions.Logging; namespace Microsoft.Azure.WebJobs.Extensions.DurableTask @@ -140,7 +141,6 @@ public void FunctionStarting( functionName, taskEventId, instanceId, - input, functionType.ToString(), ExtensionVersion, isReplay); @@ -226,7 +226,6 @@ public void FunctionCompleted( functionName, taskEventId, instanceId, - output, continuedAsNew, functionType.ToString(), ExtensionVersion, @@ -239,26 +238,6 @@ public void FunctionCompleted( } } - public void ProcessingOutOfProcPayload( - string functionName, - string taskHub, - string instanceId, - string details) - { - EtwEventSource.Instance.ProcessingOutOfProcPayload( - functionName, - taskHub, - LocalAppName, - LocalSlotName, - instanceId, - details, - ExtensionVersion); - - this.logger.LogDebug( - "{instanceId}: Function '{functionName} ({functionType})' returned the following OOProc orchestration state: {details}. : {hubName}. AppName: {appName}. SlotName: {slotName}. ExtensionVersion: {extensionVersion}. SequenceNumber: {sequenceNumber}.", - instanceId, functionName, FunctionType.Orchestrator, details, taskHub, LocalAppName, LocalSlotName, ExtensionVersion, this.sequenceNumber++); - } - public void FunctionTerminated( string hubName, string functionName, @@ -273,7 +252,6 @@ public void FunctionTerminated( LocalSlotName, functionName, instanceId, - reason, functionType.ToString(), ExtensionVersion, IsReplay: false); @@ -298,7 +276,6 @@ public void SuspendingOrchestration( LocalSlotName, functionName, instanceId, - reason, functionType.ToString(), ExtensionVersion, IsReplay: false); @@ -323,7 +300,6 @@ public void ResumingOrchestration( LocalSlotName, functionName, instanceId, - reason, functionType.ToString(), ExtensionVersion, IsReplay: false); @@ -348,7 +324,6 @@ public void FunctionRewound( LocalSlotName, functionName, instanceId, - reason, functionType.ToString(), ExtensionVersion, IsReplay: false); @@ -364,6 +339,7 @@ public void FunctionFailed( string functionName, string instanceId, string reason, + string sanitizedReason, FunctionType functionType, bool isReplay, int taskEventId = -1) @@ -377,7 +353,7 @@ public void FunctionFailed( functionName, taskEventId, instanceId, - reason, + sanitizedReason, functionType.ToString(), ExtensionVersion, isReplay); @@ -389,6 +365,19 @@ public void FunctionFailed( } } + public void FunctionFailed( + string hubName, + string functionName, + string instanceId, + Exception reason, + FunctionType functionType, + bool isReplay, + int taskEventId = -1) + { + string sanitizedException = $"{reason.GetType().FullName}\n{reason.StackTrace}"; + this.FunctionFailed(hubName, functionName, instanceId, reason.ToString(), sanitizedException, functionType, isReplay, taskEventId); + } + public void FunctionAborted( string hubName, string functionName, @@ -434,8 +423,6 @@ public void OperationCompleted( instanceId, operationId, operationName, - input, - output, duration, FunctionType.Entity.ToString(), ExtensionVersion, @@ -456,6 +443,7 @@ public void OperationFailed( string operationName, string input, string exception, + string sanitizedException, double duration, bool isReplay) { @@ -469,7 +457,6 @@ public void OperationFailed( instanceId, operationId, operationName, - input, exception, duration, FunctionType.Entity.ToString(), @@ -483,12 +470,26 @@ public void OperationFailed( } } + public void OperationFailed( + string hubName, + string functionName, + string instanceId, + string operationId, + string operationName, + string input, + Exception exception, + double duration, + bool isReplay) + { + string sanitizedException = $"{exception.GetType().FullName}\n{exception.StackTrace}"; + this.OperationFailed(hubName, functionName, instanceId, operationId, operationName, input, exception.ToString(), sanitizedException, duration, isReplay); + } + public void ExternalEventRaised( string hubName, string functionName, string instanceId, string eventName, - string input, bool isReplay) { if (this.ShouldLogEvent(isReplay)) @@ -502,7 +503,6 @@ public void ExternalEventRaised( functionName, instanceId, eventName, - input, functionType.ToString(), ExtensionVersion, isReplay); @@ -605,7 +605,6 @@ public void EntityResponseReceived( FunctionType functionType, string instanceId, string operationId, - string result, bool isReplay) { if (this.ShouldLogEvent(isReplay)) @@ -617,7 +616,6 @@ public void EntityResponseReceived( functionName, instanceId, operationId, - result, functionType.ToString(), ExtensionVersion, isReplay); @@ -806,9 +804,11 @@ public void EntityBatchFailed( string functionName, string instanceId, string traceFlags, - string details) + Exception error) { FunctionType functionType = FunctionType.Entity; + string details = Utils.IsFatal(error) ? error.GetType().Name : error.ToString(); + string sanitizedDetails = $"{error.GetType().FullName}\n{error.StackTrace}"; EtwEventSource.Instance.EntityBatchFailed( hubName, @@ -817,7 +817,7 @@ public void EntityBatchFailed( functionName, instanceId, traceFlags, - details, + sanitizedDetails, functionType.ToString(), ExtensionVersion); diff --git a/src/WebJobs.Extensions.DurableTask/EtwEventSource.cs b/src/WebJobs.Extensions.DurableTask/EtwEventSource.cs index 77f9bb0e4..8da740398 100644 --- a/src/WebJobs.Extensions.DurableTask/EtwEventSource.cs +++ b/src/WebJobs.Extensions.DurableTask/EtwEventSource.cs @@ -35,7 +35,7 @@ public void FunctionScheduled( this.WriteEvent(201, TaskHub, AppName, SlotName, FunctionName, InstanceId, Reason, FunctionType, ExtensionVersion, IsReplay); } - [Event(202, Level = EventLevel.Informational, Version = 5)] + [Event(202, Level = EventLevel.Informational, Version = 6)] public void FunctionStarting( string TaskHub, string AppName, @@ -43,12 +43,11 @@ public void FunctionStarting( string FunctionName, int TaskEventId, string InstanceId, - string Input, string FunctionType, string ExtensionVersion, bool IsReplay) { - this.WriteEvent(202, TaskHub, AppName, SlotName, FunctionName, TaskEventId, InstanceId, Input ?? "(null)", FunctionType, ExtensionVersion, IsReplay); + this.WriteEvent(202, TaskHub, AppName, SlotName, FunctionName, TaskEventId, InstanceId, FunctionType, ExtensionVersion, IsReplay); } [Event(203, Level = EventLevel.Informational, Version = 4)] @@ -80,7 +79,7 @@ public void FunctionListening( this.WriteEvent(204, TaskHub, AppName, SlotName, FunctionName, InstanceId, Reason, FunctionType, ExtensionVersion, IsReplay); } - [Event(205, Level = EventLevel.Informational, Version = 2)] + [Event(205, Level = EventLevel.Informational, Version = 3)] public void ExternalEventRaised( string TaskHub, string AppName, @@ -88,15 +87,14 @@ public void ExternalEventRaised( string FunctionName, string InstanceId, string EventName, - string Input, string FunctionType, string ExtensionVersion, bool IsReplay) { - this.WriteEvent(205, TaskHub, AppName, SlotName, FunctionName, InstanceId, EventName, Input ?? "(null)", FunctionType, ExtensionVersion, IsReplay); + this.WriteEvent(205, TaskHub, AppName, SlotName, FunctionName, InstanceId, EventName, FunctionType, ExtensionVersion, IsReplay); } - [Event(206, Level = EventLevel.Informational, Version = 5)] + [Event(206, Level = EventLevel.Informational, Version = 6)] public void FunctionCompleted( string TaskHub, string AppName, @@ -104,28 +102,26 @@ public void FunctionCompleted( string FunctionName, int TaskEventId, string InstanceId, - string Output, bool ContinuedAsNew, string FunctionType, string ExtensionVersion, bool IsReplay) { - this.WriteEvent(206, TaskHub, AppName, SlotName, FunctionName, TaskEventId, InstanceId, Output ?? "(null)", ContinuedAsNew, FunctionType, ExtensionVersion, IsReplay); + this.WriteEvent(206, TaskHub, AppName, SlotName, FunctionName, TaskEventId, InstanceId, ContinuedAsNew, FunctionType, ExtensionVersion, IsReplay); } - [Event(207, Level = EventLevel.Warning, Version = 2)] + [Event(207, Level = EventLevel.Warning, Version = 3)] public void FunctionTerminated( string TaskHub, string AppName, string SlotName, string FunctionName, string InstanceId, - string Reason, string FunctionType, string ExtensionVersion, bool IsReplay) { - this.WriteEvent(207, TaskHub, AppName, SlotName, FunctionName, InstanceId, Reason, FunctionType, ExtensionVersion, IsReplay); + this.WriteEvent(207, TaskHub, AppName, SlotName, FunctionName, InstanceId, string.Empty, FunctionType, ExtensionVersion, IsReplay); } [Event(208, Level = EventLevel.Error, Version = 4)] @@ -258,19 +254,18 @@ public void ExternalEventSaved( this.WriteEvent(215, TaskHub, AppName, SlotName, FunctionName, InstanceId, EventName, FunctionType, ExtensionVersion, IsReplay); } - [Event(216, Level = EventLevel.Informational)] + [Event(216, Level = EventLevel.Informational, Version = 2)] public void FunctionRewound( string TaskHub, string AppName, string SlotName, string FunctionName, string InstanceId, - string Reason, string FunctionType, string ExtensionVersion, bool IsReplay) { - this.WriteEvent(216, TaskHub, AppName, SlotName, FunctionName, InstanceId, Reason ?? string.Empty, FunctionType, ExtensionVersion, IsReplay); + this.WriteEvent(216, TaskHub, AppName, SlotName, FunctionName, InstanceId, FunctionType, ExtensionVersion, IsReplay); } [Event(217, Level = EventLevel.Informational)] @@ -289,7 +284,7 @@ public void EntityOperationQueued( this.WriteEvent(217, TaskHub, AppName, SlotName, FunctionName, InstanceId, OperationId, OperationName, FunctionType, ExtensionVersion, IsReplay); } - [Event(218, Level = EventLevel.Informational)] + [Event(218, Level = EventLevel.Informational, Version = 2)] public void EntityResponseReceived( string TaskHub, string AppName, @@ -297,12 +292,11 @@ public void EntityResponseReceived( string FunctionName, string InstanceId, string OperationId, - string Result, string FunctionType, string ExtensionVersion, bool IsReplay) { - this.WriteEvent(218, TaskHub, AppName, SlotName, FunctionName, InstanceId, OperationId, Result ?? "(null)", FunctionType, ExtensionVersion, IsReplay); + this.WriteEvent(218, TaskHub, AppName, SlotName, FunctionName, InstanceId, OperationId, FunctionType, ExtensionVersion, IsReplay); } [Event(219, Level = EventLevel.Informational, Version = 2)] @@ -338,7 +332,7 @@ public void EntityLockReleased( this.WriteEvent(220, TaskHub, AppName, SlotName, FunctionName, InstanceId, RequestingInstance, RequestId, FunctionType, ExtensionVersion, IsReplay); } - [Event(221, Level = EventLevel.Informational)] + [Event(221, Level = EventLevel.Informational, Version = 2)] public void OperationCompleted( string TaskHub, string AppName, @@ -347,17 +341,15 @@ public void OperationCompleted( string InstanceId, string OperationId, string OperationName, - string Input, - string Output, double Duration, string FunctionType, string ExtensionVersion, bool IsReplay) { - this.WriteEvent(221, TaskHub, AppName, SlotName, FunctionName, InstanceId, OperationId, OperationName, Input ?? "(null)", Output ?? "(null)", Duration, FunctionType, ExtensionVersion, IsReplay); + this.WriteEvent(221, TaskHub, AppName, SlotName, FunctionName, InstanceId, OperationId, OperationName, Duration, FunctionType, ExtensionVersion, IsReplay); } - [Event(222, Level = EventLevel.Error)] + [Event(222, Level = EventLevel.Error, Version = 2)] public void OperationFailed( string TaskHub, string AppName, @@ -366,14 +358,13 @@ public void OperationFailed( string InstanceId, string OperationId, string OperationName, - string Input, string Exception, double Duration, string FunctionType, string ExtensionVersion, bool IsReplay) { - this.WriteEvent(222, TaskHub, AppName, SlotName, FunctionName, InstanceId, OperationId, OperationName, Input ?? "(null)", Exception, Duration, FunctionType, ExtensionVersion, IsReplay); + this.WriteEvent(222, TaskHub, AppName, SlotName, FunctionName, InstanceId, OperationId, OperationName, Exception, Duration, FunctionType, ExtensionVersion, IsReplay); } [Event(223, Level = EventLevel.Informational)] @@ -484,34 +475,32 @@ public void TokenRenewalFailed( this.WriteEvent(230, TaskHub, AppName, SlotName, Resource, Attempt, DelayMs, Details, ExtensionVersion); } - [Event(231, Level = EventLevel.Informational, Version = 1)] + [Event(231, Level = EventLevel.Informational, Version = 2)] public void SuspendingOrchestration( string TaskHub, string AppName, string SlotName, string FunctionName, string InstanceId, - string Reason, string FunctionType, string ExtensionVersion, bool IsReplay) { - this.WriteEvent(231, TaskHub, AppName, SlotName, FunctionName, InstanceId, Reason, FunctionType, ExtensionVersion, IsReplay); + this.WriteEvent(231, TaskHub, AppName, SlotName, FunctionName, InstanceId, FunctionType, ExtensionVersion, IsReplay); } - [Event(232, Level = EventLevel.Informational, Version = 1)] + [Event(232, Level = EventLevel.Informational, Version = 2)] public void ResumingOrchestration( string TaskHub, string AppName, string SlotName, string FunctionName, string InstanceId, - string Reason, string FunctionType, string ExtensionVersion, bool IsReplay) { - this.WriteEvent(232, TaskHub, AppName, SlotName, FunctionName, InstanceId, Reason, FunctionType, ExtensionVersion, IsReplay); + this.WriteEvent(232, TaskHub, AppName, SlotName, FunctionName, InstanceId, FunctionType, ExtensionVersion, IsReplay); } [Event(233, Level = EventLevel.Informational, Version = 4)] diff --git a/src/WebJobs.Extensions.DurableTask/Listener/TaskActivityShim.cs b/src/WebJobs.Extensions.DurableTask/Listener/TaskActivityShim.cs index 9481a0be0..805cb47ab 100644 --- a/src/WebJobs.Extensions.DurableTask/Listener/TaskActivityShim.cs +++ b/src/WebJobs.Extensions.DurableTask/Listener/TaskActivityShim.cs @@ -113,7 +113,7 @@ public override async Task RunAsync(TaskContext context, string rawInput this.config.Options.HubName, this.activityName, instanceId, - exceptionToReport?.ToString() ?? string.Empty, + exceptionToReport, functionType: FunctionType.Activity, isReplay: false, taskEventId: this.taskEventId); diff --git a/src/WebJobs.Extensions.DurableTask/Listener/TaskEntityShim.cs b/src/WebJobs.Extensions.DurableTask/Listener/TaskEntityShim.cs index 1e0998ce4..f4ca2aacd 100644 --- a/src/WebJobs.Extensions.DurableTask/Listener/TaskEntityShim.cs +++ b/src/WebJobs.Extensions.DurableTask/Listener/TaskEntityShim.cs @@ -237,7 +237,7 @@ public override async Task Execute(OrchestrationContext innerContext, st this.context.Name, this.context.InstanceId, this.entityTraceInfo.TraceFlags, - this.context.InternalError.ToString()); + this.context.InternalError.SourceException); } else { @@ -547,7 +547,7 @@ private async Task ProcessOperationRequestAsync(RequestMessage request) request.Id.ToString(), request.Operation, this.Config.GetIntputOutputTrace(this.context.RawInput), - exception.ToString(), + exception, stopwatch.Elapsed.TotalMilliseconds, isReplay: false); } @@ -656,6 +656,7 @@ private async Task ExecuteOutOfProcBatch() request.Operation, this.Config.GetIntputOutputTrace(request.Input), this.Config.GetIntputOutputTrace(result.Result), + sanitizedException: string.Empty, result.DurationInMilliseconds, isReplay: false); } diff --git a/src/WebJobs.Extensions.DurableTask/Listener/TaskOrchestrationShim.cs b/src/WebJobs.Extensions.DurableTask/Listener/TaskOrchestrationShim.cs index 8cb6a33ff..7a7d2b044 100644 --- a/src/WebJobs.Extensions.DurableTask/Listener/TaskOrchestrationShim.cs +++ b/src/WebJobs.Extensions.DurableTask/Listener/TaskOrchestrationShim.cs @@ -184,14 +184,16 @@ private async Task InvokeUserCodeAndHandleResults( } catch (OrchestrationFailureException ex) { - this.TraceAndSendExceptionNotification(ex.Details); + string sanitizedException = $"{e.GetType().FullName}\n{e.StackTrace}"; + this.TraceAndSendExceptionNotification(ex.Details, sanitizedException); this.context.OrchestrationException = ExceptionDispatchInfo.Capture(ex); throw ex; } } else { - this.TraceAndSendExceptionNotification(e.ToString()); + string sanitizedException = $"{e.GetType().FullName}\n{e.StackTrace}"; + this.TraceAndSendExceptionNotification(e.ToString(), sanitizedException); var orchestrationException = new OrchestrationFailureException( $"Orchestrator function '{this.context.Name}' failed: {e.Message}", Utils.SerializeCause(e, innerContext.ErrorDataConverter)); @@ -212,13 +214,14 @@ private async Task InvokeUserCodeAndHandleResults( } } - private void TraceAndSendExceptionNotification(string exceptionDetails) + private void TraceAndSendExceptionNotification(string exceptionDetails, string sanitizedExceptionDetails) { this.config.TraceHelper.FunctionFailed( this.context.HubName, this.context.Name, this.context.InstanceId, exceptionDetails, + sanitizedReason: sanitizedExceptionDetails, FunctionType.Orchestrator, this.context.IsReplaying); diff --git a/src/WebJobs.Extensions.DurableTask/OutOfProcMiddleware.cs b/src/WebJobs.Extensions.DurableTask/OutOfProcMiddleware.cs index 8a7983cba..d15cc89d0 100644 --- a/src/WebJobs.Extensions.DurableTask/OutOfProcMiddleware.cs +++ b/src/WebJobs.Extensions.DurableTask/OutOfProcMiddleware.cs @@ -214,7 +214,7 @@ await this.LifeCycleNotificationHelper.OrchestratorCompletedAsync( isReplay: false); } } - else if (context.TryGetOrchestrationErrorDetails(out string details)) + else if (context.TryGetOrchestrationErrorDetails(out Exception? exception)) { // the function failed because the orchestrator failed. @@ -224,7 +224,7 @@ await this.LifeCycleNotificationHelper.OrchestratorCompletedAsync( this.Options.HubName, functionName.Name, instance.InstanceId, - details, + exception, FunctionType.Orchestrator, isReplay: false); @@ -232,23 +232,22 @@ await this.LifeCycleNotificationHelper.OrchestratorFailedAsync( this.Options.HubName, functionName.Name, instance.InstanceId, - details, + exception?.Message ?? string.Empty, isReplay: false); } else { // the function failed for some other reason - string exceptionDetails = functionResult.Exception.ToString(); - this.TraceHelper.FunctionFailed( this.Options.HubName, functionName.Name, instance.InstanceId, - exceptionDetails, + functionResult.Exception, FunctionType.Orchestrator, isReplay: false); + string exceptionDetails = functionResult.Exception.ToString(); await this.LifeCycleNotificationHelper.OrchestratorFailedAsync( this.Options.HubName, functionName.Name, @@ -396,7 +395,7 @@ void SetErrorResult(FailureDetails failureDetails) this.Options.HubName, functionName.Name, batchRequest.InstanceId, - functionResult.Exception.ToString(), + functionResult.Exception, FunctionType.Entity, isReplay: false); @@ -562,7 +561,7 @@ public async Task CallActivityAsync(DispatchMiddlewareContext dispatchContext, F this.Options.HubName, functionName.Name, instance.InstanceId, - result.Exception.ToString(), + result.Exception, FunctionType.Activity, isReplay: false, scheduledEvent.EventId); From a56cf6dd3033c081b107399ef4b5ee49a75acc00 Mon Sep 17 00:00:00 2001 From: David Justo Date: Mon, 10 Jun 2024 13:08:53 -0700 Subject: [PATCH 02/30] remove unecessary diff --- src/WebJobs.Extensions.DurableTask/OutOfProcMiddleware.cs | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/src/WebJobs.Extensions.DurableTask/OutOfProcMiddleware.cs b/src/WebJobs.Extensions.DurableTask/OutOfProcMiddleware.cs index d15cc89d0..eb80016e2 100644 --- a/src/WebJobs.Extensions.DurableTask/OutOfProcMiddleware.cs +++ b/src/WebJobs.Extensions.DurableTask/OutOfProcMiddleware.cs @@ -239,6 +239,8 @@ await this.LifeCycleNotificationHelper.OrchestratorFailedAsync( { // the function failed for some other reason + string exceptionDetails = functionResult.Exception.ToString(); + this.TraceHelper.FunctionFailed( this.Options.HubName, functionName.Name, @@ -247,7 +249,6 @@ await this.LifeCycleNotificationHelper.OrchestratorFailedAsync( FunctionType.Orchestrator, isReplay: false); - string exceptionDetails = functionResult.Exception.ToString(); await this.LifeCycleNotificationHelper.OrchestratorFailedAsync( this.Options.HubName, functionName.Name, From ffdd81c27298f40799035734217df80c9f2b5179 Mon Sep 17 00:00:00 2001 From: David Justo Date: Mon, 10 Jun 2024 13:16:33 -0700 Subject: [PATCH 03/30] refactor --- .../Listener/TaskOrchestrationShim.cs | 16 +++++++++++----- 1 file changed, 11 insertions(+), 5 deletions(-) diff --git a/src/WebJobs.Extensions.DurableTask/Listener/TaskOrchestrationShim.cs b/src/WebJobs.Extensions.DurableTask/Listener/TaskOrchestrationShim.cs index 7a7d2b044..61c399dcd 100644 --- a/src/WebJobs.Extensions.DurableTask/Listener/TaskOrchestrationShim.cs +++ b/src/WebJobs.Extensions.DurableTask/Listener/TaskOrchestrationShim.cs @@ -184,16 +184,14 @@ private async Task InvokeUserCodeAndHandleResults( } catch (OrchestrationFailureException ex) { - string sanitizedException = $"{e.GetType().FullName}\n{e.StackTrace}"; - this.TraceAndSendExceptionNotification(ex.Details, sanitizedException); + this.TraceAndSendExceptionNotification(ex); this.context.OrchestrationException = ExceptionDispatchInfo.Capture(ex); throw ex; } } else { - string sanitizedException = $"{e.GetType().FullName}\n{e.StackTrace}"; - this.TraceAndSendExceptionNotification(e.ToString(), sanitizedException); + this.TraceAndSendExceptionNotification(e); var orchestrationException = new OrchestrationFailureException( $"Orchestrator function '{this.context.Name}' failed: {e.Message}", Utils.SerializeCause(e, innerContext.ErrorDataConverter)); @@ -214,8 +212,16 @@ private async Task InvokeUserCodeAndHandleResults( } } - private void TraceAndSendExceptionNotification(string exceptionDetails, string sanitizedExceptionDetails) + private void TraceAndSendExceptionNotification(Exception exception) { + string exceptionDetails = exception.Message; + if (exception is OrchestrationFailureException orchestrationFailureException) + { + exceptionDetails = orchestrationFailureException.Details; + } + + string sanitizedExceptionDetails = $"{exception.GetType().FullName}\n{exception.StackTrace}"; + this.config.TraceHelper.FunctionFailed( this.context.HubName, this.context.Name, From 17dceeb4f2a2285ab2f4b02abd5e11220ace1696 Mon Sep 17 00:00:00 2001 From: David Justo Date: Mon, 10 Jun 2024 13:32:25 -0700 Subject: [PATCH 04/30] refactor --- .../DurableOrchestrationContext.cs | 3 +- .../EndToEndTraceHelper.cs | 32 ++++++++++--------- .../Listener/TaskOrchestrationShim.cs | 5 +-- 3 files changed, 19 insertions(+), 21 deletions(-) diff --git a/src/WebJobs.Extensions.DurableTask/ContextImplementations/DurableOrchestrationContext.cs b/src/WebJobs.Extensions.DurableTask/ContextImplementations/DurableOrchestrationContext.cs index ff6c9f696..86cefea95 100644 --- a/src/WebJobs.Extensions.DurableTask/ContextImplementations/DurableOrchestrationContext.cs +++ b/src/WebJobs.Extensions.DurableTask/ContextImplementations/DurableOrchestrationContext.cs @@ -792,8 +792,7 @@ internal async Task CallDurableTaskFunctionAsync( this.Config.Options.HubName, functionName, this.InstanceId, - reason: $"(replayed {exception.GetType().Name})", - sanitizedReason: string.Empty, + exception: exception, functionType: functionType, isReplay: true); } diff --git a/src/WebJobs.Extensions.DurableTask/EndToEndTraceHelper.cs b/src/WebJobs.Extensions.DurableTask/EndToEndTraceHelper.cs index 9075e4c67..45f7a9548 100644 --- a/src/WebJobs.Extensions.DurableTask/EndToEndTraceHelper.cs +++ b/src/WebJobs.Extensions.DurableTask/EndToEndTraceHelper.cs @@ -5,6 +5,7 @@ using System.Diagnostics; using System.Net; using DurableTask.Core.Common; +using DurableTask.Core.Exceptions; using Microsoft.Extensions.Logging; namespace Microsoft.Azure.WebJobs.Extensions.DurableTask @@ -338,12 +339,26 @@ public void FunctionFailed( string hubName, string functionName, string instanceId, - string reason, - string sanitizedReason, + Exception exception, FunctionType functionType, bool isReplay, int taskEventId = -1) { + + string reason = exception.Message; + if (exception is OrchestrationFailureException orchestrationFailureException) + { + reason = orchestrationFailureException.Details; + } + + string sanitizedReason = $"{exception.GetType().FullName}\n{exception.StackTrace}"; + + if (isReplay) + { + reason = $"(replayed {exception.GetType().Name})"; + sanitizedReason = reason; + } + if (this.ShouldLogEvent(isReplay)) { EtwEventSource.Instance.FunctionFailed( @@ -365,19 +380,6 @@ public void FunctionFailed( } } - public void FunctionFailed( - string hubName, - string functionName, - string instanceId, - Exception reason, - FunctionType functionType, - bool isReplay, - int taskEventId = -1) - { - string sanitizedException = $"{reason.GetType().FullName}\n{reason.StackTrace}"; - this.FunctionFailed(hubName, functionName, instanceId, reason.ToString(), sanitizedException, functionType, isReplay, taskEventId); - } - public void FunctionAborted( string hubName, string functionName, diff --git a/src/WebJobs.Extensions.DurableTask/Listener/TaskOrchestrationShim.cs b/src/WebJobs.Extensions.DurableTask/Listener/TaskOrchestrationShim.cs index 61c399dcd..89e239dce 100644 --- a/src/WebJobs.Extensions.DurableTask/Listener/TaskOrchestrationShim.cs +++ b/src/WebJobs.Extensions.DurableTask/Listener/TaskOrchestrationShim.cs @@ -220,14 +220,11 @@ private void TraceAndSendExceptionNotification(Exception exception) exceptionDetails = orchestrationFailureException.Details; } - string sanitizedExceptionDetails = $"{exception.GetType().FullName}\n{exception.StackTrace}"; - this.config.TraceHelper.FunctionFailed( this.context.HubName, this.context.Name, this.context.InstanceId, - exceptionDetails, - sanitizedReason: sanitizedExceptionDetails, + exception: exception, FunctionType.Orchestrator, this.context.IsReplaying); From ba345d16cad49d7abb6808d1d6be29f1feb8ef07 Mon Sep 17 00:00:00 2001 From: David Justo Date: Tue, 11 Jun 2024 09:23:38 -0700 Subject: [PATCH 05/30] Refactor --- .../DurableOrchestrationContext.cs | 3 +- .../EndToEndTraceHelper.cs | 49 +++++++++++++------ .../Listener/TaskEntityShim.cs | 1 - 3 files changed, 34 insertions(+), 19 deletions(-) diff --git a/src/WebJobs.Extensions.DurableTask/ContextImplementations/DurableOrchestrationContext.cs b/src/WebJobs.Extensions.DurableTask/ContextImplementations/DurableOrchestrationContext.cs index 86cefea95..01d2d3387 100644 --- a/src/WebJobs.Extensions.DurableTask/ContextImplementations/DurableOrchestrationContext.cs +++ b/src/WebJobs.Extensions.DurableTask/ContextImplementations/DurableOrchestrationContext.cs @@ -781,8 +781,7 @@ internal async Task CallDurableTaskFunctionAsync( operationId, operationName, input: "(replayed)", - exception: "(replayed)", - sanitizedException: string.Empty, + exception: exception, duration: 0, isReplay: true); } diff --git a/src/WebJobs.Extensions.DurableTask/EndToEndTraceHelper.cs b/src/WebJobs.Extensions.DurableTask/EndToEndTraceHelper.cs index 45f7a9548..e181b6dea 100644 --- a/src/WebJobs.Extensions.DurableTask/EndToEndTraceHelper.cs +++ b/src/WebJobs.Extensions.DurableTask/EndToEndTraceHelper.cs @@ -358,6 +358,19 @@ public void FunctionFailed( reason = $"(replayed {exception.GetType().Name})"; sanitizedReason = reason; } + this.FunctionFailed(hubName, functionName, instanceId, reason, sanitizedReason, functionType, isReplay, taskEventId); + } + + public void FunctionFailed( + string hubName, + string functionName, + string instanceId, + string reason, + string sanitizedReason, + FunctionType functionType, + bool isReplay, + int taskEventId = -1) + { if (this.ShouldLogEvent(isReplay)) { @@ -437,6 +450,26 @@ public void OperationCompleted( } } + public void OperationFailed( + string hubName, + string functionName, + string instanceId, + string operationId, + string operationName, + string input, + Exception exception, + double duration, + bool isReplay) + { + string exceptionString = exception.ToString(); + if (isReplay) + { + exceptionString = $"(replayed {exception.GetType().Name})"; + } + + this.OperationFailed(hubName, functionName, instanceId, operationId, operationName, input, exceptionString, duration, isReplay); + } + public void OperationFailed( string hubName, string functionName, @@ -445,7 +478,6 @@ public void OperationFailed( string operationName, string input, string exception, - string sanitizedException, double duration, bool isReplay) { @@ -472,21 +504,6 @@ public void OperationFailed( } } - public void OperationFailed( - string hubName, - string functionName, - string instanceId, - string operationId, - string operationName, - string input, - Exception exception, - double duration, - bool isReplay) - { - string sanitizedException = $"{exception.GetType().FullName}\n{exception.StackTrace}"; - this.OperationFailed(hubName, functionName, instanceId, operationId, operationName, input, exception.ToString(), sanitizedException, duration, isReplay); - } - public void ExternalEventRaised( string hubName, string functionName, diff --git a/src/WebJobs.Extensions.DurableTask/Listener/TaskEntityShim.cs b/src/WebJobs.Extensions.DurableTask/Listener/TaskEntityShim.cs index f4ca2aacd..1c61b8673 100644 --- a/src/WebJobs.Extensions.DurableTask/Listener/TaskEntityShim.cs +++ b/src/WebJobs.Extensions.DurableTask/Listener/TaskEntityShim.cs @@ -656,7 +656,6 @@ private async Task ExecuteOutOfProcBatch() request.Operation, this.Config.GetIntputOutputTrace(request.Input), this.Config.GetIntputOutputTrace(result.Result), - sanitizedException: string.Empty, result.DurationInMilliseconds, isReplay: false); } From 77ebaa6236cb8b66c1333a764b64fdd78649de5f Mon Sep 17 00:00:00 2001 From: David Justo Date: Tue, 11 Jun 2024 10:00:57 -0700 Subject: [PATCH 06/30] refactor --- .../DurableOrchestrationContext.cs | 2 + .../DurableTaskExtension.cs | 6 +- .../EndToEndTraceHelper.cs | 84 ++++++++++++++++++- .../EtwEventSource.cs | 49 ++++++----- .../Listener/TaskActivityShim.cs | 4 +- .../Listener/TaskEntityShim.cs | 12 +-- .../Listener/TaskOrchestrationShim.cs | 4 +- .../OutOfProcMiddleware.cs | 12 +-- 8 files changed, 133 insertions(+), 40 deletions(-) diff --git a/src/WebJobs.Extensions.DurableTask/ContextImplementations/DurableOrchestrationContext.cs b/src/WebJobs.Extensions.DurableTask/ContextImplementations/DurableOrchestrationContext.cs index 01d2d3387..782a4c8b1 100644 --- a/src/WebJobs.Extensions.DurableTask/ContextImplementations/DurableOrchestrationContext.cs +++ b/src/WebJobs.Extensions.DurableTask/ContextImplementations/DurableOrchestrationContext.cs @@ -933,6 +933,7 @@ internal void RaiseEvent(string name, string input) FunctionType.Orchestrator, this.InstanceId, name, + responseMessage.Result, this.IsReplaying); } else @@ -942,6 +943,7 @@ internal void RaiseEvent(string name, string input) this.Name, this.InstanceId, name, + input, this.IsReplaying); } diff --git a/src/WebJobs.Extensions.DurableTask/DurableTaskExtension.cs b/src/WebJobs.Extensions.DurableTask/DurableTaskExtension.cs index 0af7dbbc3..fdf9096cf 100644 --- a/src/WebJobs.Extensions.DurableTask/DurableTaskExtension.cs +++ b/src/WebJobs.Extensions.DurableTask/DurableTaskExtension.cs @@ -154,7 +154,7 @@ public DurableTaskExtension( ILogger logger = loggerFactory.CreateLogger(LoggerCategoryName); - this.TraceHelper = new EndToEndTraceHelper(logger, this.Options.Tracing.TraceReplayEvents); + this.TraceHelper = new EndToEndTraceHelper(logger, this.Options.Tracing.TraceReplayEvents, this.Options.Tracing.TraceInputsAndOutputs); this.LifeCycleNotificationHelper = lifeCycleNotificationHelper ?? this.CreateLifeCycleNotificationHelper(); this.durabilityProviderFactory = GetDurabilityProviderFactory(this.Options, logger, orchestrationServiceFactories); this.defaultDurabilityProvider = this.durabilityProviderFactory.GetDurabilityProvider(); @@ -1037,7 +1037,7 @@ private async Task EntityMiddleware(DispatchMiddlewareContext dispatchContext, F entityContext.HubName, entityContext.Name, entityContext.InstanceId, - this.GetIntputOutputTrace(runtimeState.Input), + runtimeState.Input, FunctionType.Entity, isReplay: false); @@ -1080,7 +1080,7 @@ private async Task EntityMiddleware(DispatchMiddlewareContext dispatchContext, F entityContext.HubName, entityContext.Name, entityContext.InstanceId, - this.GetIntputOutputTrace(entityContext.State.EntityState), + entityContext.State.EntityState, continuedAsNew: true, functionType: FunctionType.Entity, isReplay: false); diff --git a/src/WebJobs.Extensions.DurableTask/EndToEndTraceHelper.cs b/src/WebJobs.Extensions.DurableTask/EndToEndTraceHelper.cs index e181b6dea..4304db7a7 100644 --- a/src/WebJobs.Extensions.DurableTask/EndToEndTraceHelper.cs +++ b/src/WebJobs.Extensions.DurableTask/EndToEndTraceHelper.cs @@ -19,13 +19,15 @@ internal class EndToEndTraceHelper private readonly ILogger logger; private readonly bool traceReplayEvents; + private readonly bool shouldCensor; private long sequenceNumber; - public EndToEndTraceHelper(ILogger logger, bool traceReplayEvents) + public EndToEndTraceHelper(ILogger logger, bool traceReplayEvents, bool shouldCensor = false) { this.logger = logger ?? throw new ArgumentNullException(nameof(logger)); this.traceReplayEvents = traceReplayEvents; + this.shouldCensor = shouldCensor; } public static string LocalAppName @@ -123,16 +125,28 @@ public void FunctionScheduled( LocalAppName, LocalSlotName, ExtensionVersion, this.sequenceNumber++); } } +#nullable enable public void FunctionStarting( string hubName, string functionName, string instanceId, - string input, + string? input, FunctionType functionType, bool isReplay, int taskEventId = -1) { + + if (this.shouldCensor) + { + input = ""; + } + + if (isReplay) + { + input = "(replay)"; + } + if (this.ShouldLogEvent(isReplay)) { EtwEventSource.Instance.FunctionStarting( @@ -142,6 +156,7 @@ public void FunctionStarting( functionName, taskEventId, instanceId, + input, functionType.ToString(), ExtensionVersion, isReplay); @@ -152,6 +167,7 @@ public void FunctionStarting( LocalAppName, LocalSlotName, ExtensionVersion, this.sequenceNumber++, taskEventId); } } +#nullable disable public void FunctionAwaited( string hubName, @@ -218,6 +234,16 @@ public void FunctionCompleted( bool isReplay, int taskEventId = -1) { + if (this.shouldCensor) + { + output = ""; + } + + if (isReplay) + { + output = "(replay)"; + } + if (this.ShouldLogEvent(isReplay)) { EtwEventSource.Instance.FunctionCompleted( @@ -227,6 +253,7 @@ public void FunctionCompleted( functionName, taskEventId, instanceId, + output, continuedAsNew, functionType.ToString(), ExtensionVersion, @@ -245,6 +272,11 @@ public void FunctionTerminated( string instanceId, string reason) { + if (this.shouldCensor) + { + reason = ""; + } + FunctionType functionType = FunctionType.Orchestrator; EtwEventSource.Instance.FunctionTerminated( @@ -253,6 +285,7 @@ public void FunctionTerminated( LocalSlotName, functionName, instanceId, + reason, functionType.ToString(), ExtensionVersion, IsReplay: false); @@ -269,6 +302,11 @@ public void SuspendingOrchestration( string instanceId, string reason) { + if (this.shouldCensor) + { + reason = ""; + } + FunctionType functionType = FunctionType.Orchestrator; EtwEventSource.Instance.SuspendingOrchestration( @@ -277,6 +315,7 @@ public void SuspendingOrchestration( LocalSlotName, functionName, instanceId, + reason, functionType.ToString(), ExtensionVersion, IsReplay: false); @@ -293,6 +332,11 @@ public void ResumingOrchestration( string instanceId, string reason) { + if (this.shouldCensor) + { + reason = ""; + } + FunctionType functionType = FunctionType.Orchestrator; EtwEventSource.Instance.ResumingOrchestration( @@ -301,6 +345,7 @@ public void ResumingOrchestration( LocalSlotName, functionName, instanceId, + reason, functionType.ToString(), ExtensionVersion, IsReplay: false); @@ -317,6 +362,11 @@ public void FunctionRewound( string instanceId, string reason) { + if (this.shouldCensor) + { + reason = ""; + } + FunctionType functionType = FunctionType.Orchestrator; EtwEventSource.Instance.FunctionRewound( @@ -325,6 +375,7 @@ public void FunctionRewound( LocalSlotName, functionName, instanceId, + reason, functionType.ToString(), ExtensionVersion, IsReplay: false); @@ -428,6 +479,12 @@ public void OperationCompleted( double duration, bool isReplay) { + if (this.shouldCensor) + { + input = ""; + output = ""; + } + if (this.ShouldLogEvent(isReplay)) { EtwEventSource.Instance.OperationCompleted( @@ -438,6 +495,8 @@ public void OperationCompleted( instanceId, operationId, operationName, + input, + output, duration, FunctionType.Entity.ToString(), ExtensionVersion, @@ -481,6 +540,12 @@ public void OperationFailed( double duration, bool isReplay) { + if (this.shouldCensor) + { + input = ""; + exception = ""; + } + if (this.ShouldLogEvent(isReplay)) { EtwEventSource.Instance.OperationFailed( @@ -491,6 +556,7 @@ public void OperationFailed( instanceId, operationId, operationName, + input, exception, duration, FunctionType.Entity.ToString(), @@ -509,8 +575,14 @@ public void ExternalEventRaised( string functionName, string instanceId, string eventName, + string input, bool isReplay) { + if (this.shouldCensor) + { + input = ""; + } + if (this.ShouldLogEvent(isReplay)) { FunctionType functionType = FunctionType.Orchestrator; @@ -522,6 +594,7 @@ public void ExternalEventRaised( functionName, instanceId, eventName, + input, functionType.ToString(), ExtensionVersion, isReplay); @@ -624,8 +697,14 @@ public void EntityResponseReceived( FunctionType functionType, string instanceId, string operationId, + string result, bool isReplay) { + if (this.shouldCensor) + { + result = ""; + } + if (this.ShouldLogEvent(isReplay)) { EtwEventSource.Instance.EntityResponseReceived( @@ -635,6 +714,7 @@ public void EntityResponseReceived( functionName, instanceId, operationId, + result, functionType.ToString(), ExtensionVersion, isReplay); diff --git a/src/WebJobs.Extensions.DurableTask/EtwEventSource.cs b/src/WebJobs.Extensions.DurableTask/EtwEventSource.cs index 8da740398..74930ad9b 100644 --- a/src/WebJobs.Extensions.DurableTask/EtwEventSource.cs +++ b/src/WebJobs.Extensions.DurableTask/EtwEventSource.cs @@ -35,7 +35,7 @@ public void FunctionScheduled( this.WriteEvent(201, TaskHub, AppName, SlotName, FunctionName, InstanceId, Reason, FunctionType, ExtensionVersion, IsReplay); } - [Event(202, Level = EventLevel.Informational, Version = 6)] + [Event(202, Level = EventLevel.Informational, Version = 5)] public void FunctionStarting( string TaskHub, string AppName, @@ -43,11 +43,12 @@ public void FunctionStarting( string FunctionName, int TaskEventId, string InstanceId, + string Input, string FunctionType, string ExtensionVersion, bool IsReplay) { - this.WriteEvent(202, TaskHub, AppName, SlotName, FunctionName, TaskEventId, InstanceId, FunctionType, ExtensionVersion, IsReplay); + this.WriteEvent(202, TaskHub, AppName, SlotName, FunctionName, TaskEventId, InstanceId, Input ?? "(null)", FunctionType, ExtensionVersion, IsReplay); } [Event(203, Level = EventLevel.Informational, Version = 4)] @@ -79,7 +80,7 @@ public void FunctionListening( this.WriteEvent(204, TaskHub, AppName, SlotName, FunctionName, InstanceId, Reason, FunctionType, ExtensionVersion, IsReplay); } - [Event(205, Level = EventLevel.Informational, Version = 3)] + [Event(205, Level = EventLevel.Informational, Version = 2)] public void ExternalEventRaised( string TaskHub, string AppName, @@ -87,14 +88,15 @@ public void ExternalEventRaised( string FunctionName, string InstanceId, string EventName, + string Input, string FunctionType, string ExtensionVersion, bool IsReplay) { - this.WriteEvent(205, TaskHub, AppName, SlotName, FunctionName, InstanceId, EventName, FunctionType, ExtensionVersion, IsReplay); + this.WriteEvent(205, TaskHub, AppName, SlotName, FunctionName, InstanceId, EventName, Input ?? "(null)", FunctionType, ExtensionVersion, IsReplay); } - [Event(206, Level = EventLevel.Informational, Version = 6)] + [Event(206, Level = EventLevel.Informational, Version = 5)] public void FunctionCompleted( string TaskHub, string AppName, @@ -102,12 +104,13 @@ public void FunctionCompleted( string FunctionName, int TaskEventId, string InstanceId, + string Output, bool ContinuedAsNew, string FunctionType, string ExtensionVersion, bool IsReplay) { - this.WriteEvent(206, TaskHub, AppName, SlotName, FunctionName, TaskEventId, InstanceId, ContinuedAsNew, FunctionType, ExtensionVersion, IsReplay); + this.WriteEvent(206, TaskHub, AppName, SlotName, FunctionName, TaskEventId, InstanceId, Output ?? "(null)", ContinuedAsNew, FunctionType, ExtensionVersion, IsReplay); } [Event(207, Level = EventLevel.Warning, Version = 3)] @@ -117,11 +120,12 @@ public void FunctionTerminated( string SlotName, string FunctionName, string InstanceId, + string Reason, string FunctionType, string ExtensionVersion, bool IsReplay) { - this.WriteEvent(207, TaskHub, AppName, SlotName, FunctionName, InstanceId, string.Empty, FunctionType, ExtensionVersion, IsReplay); + this.WriteEvent(207, TaskHub, AppName, SlotName, FunctionName, InstanceId, Reason, FunctionType, ExtensionVersion, IsReplay); } [Event(208, Level = EventLevel.Error, Version = 4)] @@ -254,18 +258,19 @@ public void ExternalEventSaved( this.WriteEvent(215, TaskHub, AppName, SlotName, FunctionName, InstanceId, EventName, FunctionType, ExtensionVersion, IsReplay); } - [Event(216, Level = EventLevel.Informational, Version = 2)] + [Event(216, Level = EventLevel.Informational)] public void FunctionRewound( string TaskHub, string AppName, string SlotName, string FunctionName, string InstanceId, + string Reason, string FunctionType, string ExtensionVersion, bool IsReplay) { - this.WriteEvent(216, TaskHub, AppName, SlotName, FunctionName, InstanceId, FunctionType, ExtensionVersion, IsReplay); + this.WriteEvent(216, TaskHub, AppName, SlotName, FunctionName, InstanceId, Reason ?? string.Empty, FunctionType, ExtensionVersion, IsReplay); } [Event(217, Level = EventLevel.Informational)] @@ -284,7 +289,7 @@ public void EntityOperationQueued( this.WriteEvent(217, TaskHub, AppName, SlotName, FunctionName, InstanceId, OperationId, OperationName, FunctionType, ExtensionVersion, IsReplay); } - [Event(218, Level = EventLevel.Informational, Version = 2)] + [Event(218, Level = EventLevel.Informational)] public void EntityResponseReceived( string TaskHub, string AppName, @@ -292,11 +297,12 @@ public void EntityResponseReceived( string FunctionName, string InstanceId, string OperationId, + string Result, string FunctionType, string ExtensionVersion, bool IsReplay) { - this.WriteEvent(218, TaskHub, AppName, SlotName, FunctionName, InstanceId, OperationId, FunctionType, ExtensionVersion, IsReplay); + this.WriteEvent(218, TaskHub, AppName, SlotName, FunctionName, InstanceId, Result ?? "(null)", OperationId, FunctionType, ExtensionVersion, IsReplay); } [Event(219, Level = EventLevel.Informational, Version = 2)] @@ -332,7 +338,7 @@ public void EntityLockReleased( this.WriteEvent(220, TaskHub, AppName, SlotName, FunctionName, InstanceId, RequestingInstance, RequestId, FunctionType, ExtensionVersion, IsReplay); } - [Event(221, Level = EventLevel.Informational, Version = 2)] + [Event(221, Level = EventLevel.Informational)] public void OperationCompleted( string TaskHub, string AppName, @@ -341,15 +347,17 @@ public void OperationCompleted( string InstanceId, string OperationId, string OperationName, + string Input, + string Output, double Duration, string FunctionType, string ExtensionVersion, bool IsReplay) { - this.WriteEvent(221, TaskHub, AppName, SlotName, FunctionName, InstanceId, OperationId, OperationName, Duration, FunctionType, ExtensionVersion, IsReplay); + this.WriteEvent(221, TaskHub, AppName, SlotName, FunctionName, InstanceId, OperationId, OperationName, Input ?? "(null)", Output ?? "(null)", Duration, FunctionType, ExtensionVersion, IsReplay); } - [Event(222, Level = EventLevel.Error, Version = 2)] + [Event(222, Level = EventLevel.Error)] public void OperationFailed( string TaskHub, string AppName, @@ -358,13 +366,14 @@ public void OperationFailed( string InstanceId, string OperationId, string OperationName, + string Input, string Exception, double Duration, string FunctionType, string ExtensionVersion, bool IsReplay) { - this.WriteEvent(222, TaskHub, AppName, SlotName, FunctionName, InstanceId, OperationId, OperationName, Exception, Duration, FunctionType, ExtensionVersion, IsReplay); + this.WriteEvent(222, TaskHub, AppName, SlotName, FunctionName, InstanceId, OperationId, OperationName, Input ?? "(null)", Exception, Duration, FunctionType, ExtensionVersion, IsReplay); } [Event(223, Level = EventLevel.Informational)] @@ -475,32 +484,34 @@ public void TokenRenewalFailed( this.WriteEvent(230, TaskHub, AppName, SlotName, Resource, Attempt, DelayMs, Details, ExtensionVersion); } - [Event(231, Level = EventLevel.Informational, Version = 2)] + [Event(231, Level = EventLevel.Informational, Version = 1)] public void SuspendingOrchestration( string TaskHub, string AppName, string SlotName, string FunctionName, string InstanceId, + string Reason, string FunctionType, string ExtensionVersion, bool IsReplay) { - this.WriteEvent(231, TaskHub, AppName, SlotName, FunctionName, InstanceId, FunctionType, ExtensionVersion, IsReplay); + this.WriteEvent(231, TaskHub, AppName, SlotName, FunctionName, InstanceId, Reason, FunctionType, ExtensionVersion, IsReplay); } - [Event(232, Level = EventLevel.Informational, Version = 2)] + [Event(232, Level = EventLevel.Informational, Version = 1)] public void ResumingOrchestration( string TaskHub, string AppName, string SlotName, string FunctionName, string InstanceId, + string Reason, string FunctionType, string ExtensionVersion, bool IsReplay) { - this.WriteEvent(232, TaskHub, AppName, SlotName, FunctionName, InstanceId, FunctionType, ExtensionVersion, IsReplay); + this.WriteEvent(232, TaskHub, AppName, SlotName, FunctionName, InstanceId, Reason, FunctionType, ExtensionVersion, IsReplay); } [Event(233, Level = EventLevel.Informational, Version = 4)] diff --git a/src/WebJobs.Extensions.DurableTask/Listener/TaskActivityShim.cs b/src/WebJobs.Extensions.DurableTask/Listener/TaskActivityShim.cs index 805cb47ab..2e356d66f 100644 --- a/src/WebJobs.Extensions.DurableTask/Listener/TaskActivityShim.cs +++ b/src/WebJobs.Extensions.DurableTask/Listener/TaskActivityShim.cs @@ -58,7 +58,7 @@ public override async Task RunAsync(TaskContext context, string rawInput this.config.Options.HubName, this.activityName, instanceId, - this.config.GetIntputOutputTrace(rawInput), + rawInput, functionType: FunctionType.Activity, isReplay: false, taskEventId: this.taskEventId); @@ -76,7 +76,7 @@ public override async Task RunAsync(TaskContext context, string rawInput this.config.Options.HubName, this.activityName, instanceId, - this.config.GetIntputOutputTrace(serializedOutput), + serializedOutput, continuedAsNew: false, functionType: FunctionType.Activity, isReplay: false, diff --git a/src/WebJobs.Extensions.DurableTask/Listener/TaskEntityShim.cs b/src/WebJobs.Extensions.DurableTask/Listener/TaskEntityShim.cs index 1c61b8673..975e7b640 100644 --- a/src/WebJobs.Extensions.DurableTask/Listener/TaskEntityShim.cs +++ b/src/WebJobs.Extensions.DurableTask/Listener/TaskEntityShim.cs @@ -533,8 +533,8 @@ private async Task ProcessOperationRequestAsync(RequestMessage request) this.context.InstanceId, request.Id.ToString(), request.Operation, - this.Config.GetIntputOutputTrace(this.context.RawInput), - this.Config.GetIntputOutputTrace(response.Result), + this.context.RawInput, + response.Result, stopwatch.Elapsed.TotalMilliseconds, isReplay: false); } @@ -638,8 +638,8 @@ private async Task ExecuteOutOfProcBatch() this.context.InstanceId, request.Id.ToString(), request.Operation, - this.Config.GetIntputOutputTrace(request.Input), - this.Config.GetIntputOutputTrace(result.Result), + request.Input, + result.Result, result.DurationInMilliseconds, isReplay: false); } @@ -654,8 +654,8 @@ private async Task ExecuteOutOfProcBatch() this.context.InstanceId, request.Id.ToString(), request.Operation, - this.Config.GetIntputOutputTrace(request.Input), - this.Config.GetIntputOutputTrace(result.Result), + request.Input, + result.Result, result.DurationInMilliseconds, isReplay: false); } diff --git a/src/WebJobs.Extensions.DurableTask/Listener/TaskOrchestrationShim.cs b/src/WebJobs.Extensions.DurableTask/Listener/TaskOrchestrationShim.cs index 89e239dce..3f127dca5 100644 --- a/src/WebJobs.Extensions.DurableTask/Listener/TaskOrchestrationShim.cs +++ b/src/WebJobs.Extensions.DurableTask/Listener/TaskOrchestrationShim.cs @@ -75,7 +75,7 @@ public override async Task Execute(OrchestrationContext innerContext, st this.context.HubName, this.context.Name, this.context.InstanceId, - this.Config.GetIntputOutputTrace(serializedInput), + serializedInput, FunctionType.Orchestrator, this.context.IsReplaying); status = OrchestrationRuntimeStatus.Running; @@ -113,7 +113,7 @@ public override async Task Execute(OrchestrationContext innerContext, st this.context.HubName, this.context.Name, this.context.InstanceId, - this.Config.GetIntputOutputTrace(serializedOutput), + serializedOutput, this.context.ContinuedAsNew, FunctionType.Orchestrator, this.context.IsReplaying); diff --git a/src/WebJobs.Extensions.DurableTask/OutOfProcMiddleware.cs b/src/WebJobs.Extensions.DurableTask/OutOfProcMiddleware.cs index eb80016e2..4d514c670 100644 --- a/src/WebJobs.Extensions.DurableTask/OutOfProcMiddleware.cs +++ b/src/WebJobs.Extensions.DurableTask/OutOfProcMiddleware.cs @@ -95,7 +95,7 @@ public async Task CallOrchestratorAsync(DispatchMiddlewareContext dispatchContex this.Options.HubName, functionName.Name, instance.InstanceId, - isReplaying ? "(replay)" : this.extension.GetIntputOutputTrace(startEvent.Input), + startEvent.Input, FunctionType.Orchestrator, isReplaying); @@ -188,7 +188,7 @@ await this.LifeCycleNotificationHelper.OrchestratorStartingAsync( this.Options.HubName, functionName.Name, instance.InstanceId, - this.extension.GetIntputOutputTrace(context.SerializedOutput), + context.SerializedOutput, context.ContinuedAsNew, FunctionType.Orchestrator, isReplay: false); @@ -320,7 +320,7 @@ void SetErrorResult(FailureDetails failureDetails) this.Options.HubName, functionName.Name, batchRequest.InstanceId, - this.extension.GetIntputOutputTrace(batchRequest.EntityState), + batchRequest.EntityState, functionType: FunctionType.Entity, isReplay: false); @@ -429,7 +429,7 @@ void SetErrorResult(FailureDetails failureDetails) this.Options.HubName, functionName.Name, batchRequest.InstanceId, - this.extension.GetIntputOutputTrace(batchRequest.EntityState), + batchRequest.EntityState, batchResult.EntityState != null, FunctionType.Entity, isReplay: false); @@ -496,7 +496,7 @@ public async Task CallActivityAsync(DispatchMiddlewareContext dispatchContext, F this.Options.HubName, functionName.Name, instance.InstanceId, - this.extension.GetIntputOutputTrace(rawInput), + rawInput, functionType: FunctionType.Activity, isReplay: false, taskEventId: scheduledEvent.EventId); @@ -542,7 +542,7 @@ public async Task CallActivityAsync(DispatchMiddlewareContext dispatchContext, F this.Options.HubName, functionName.Name, instance.InstanceId, - this.extension.GetIntputOutputTrace(serializedOutput), + serializedOutput, continuedAsNew: false, FunctionType.Activity, isReplay: false, From e1e865ca8402ed5b3635232b9f4f747c48ebd022 Mon Sep 17 00:00:00 2001 From: David Justo Date: Tue, 11 Jun 2024 10:04:06 -0700 Subject: [PATCH 07/30] remove unecessary diff --- src/WebJobs.Extensions.DurableTask/EtwEventSource.cs | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/src/WebJobs.Extensions.DurableTask/EtwEventSource.cs b/src/WebJobs.Extensions.DurableTask/EtwEventSource.cs index 74930ad9b..77f9bb0e4 100644 --- a/src/WebJobs.Extensions.DurableTask/EtwEventSource.cs +++ b/src/WebJobs.Extensions.DurableTask/EtwEventSource.cs @@ -113,7 +113,7 @@ public void FunctionCompleted( this.WriteEvent(206, TaskHub, AppName, SlotName, FunctionName, TaskEventId, InstanceId, Output ?? "(null)", ContinuedAsNew, FunctionType, ExtensionVersion, IsReplay); } - [Event(207, Level = EventLevel.Warning, Version = 3)] + [Event(207, Level = EventLevel.Warning, Version = 2)] public void FunctionTerminated( string TaskHub, string AppName, @@ -302,7 +302,7 @@ public void EntityResponseReceived( string ExtensionVersion, bool IsReplay) { - this.WriteEvent(218, TaskHub, AppName, SlotName, FunctionName, InstanceId, Result ?? "(null)", OperationId, FunctionType, ExtensionVersion, IsReplay); + this.WriteEvent(218, TaskHub, AppName, SlotName, FunctionName, InstanceId, OperationId, Result ?? "(null)", FunctionType, ExtensionVersion, IsReplay); } [Event(219, Level = EventLevel.Informational, Version = 2)] From 6bd3a338a544c022c7def52fc26b67908d6ccb6f Mon Sep 17 00:00:00 2001 From: David Justo Date: Tue, 11 Jun 2024 10:11:48 -0700 Subject: [PATCH 08/30] add nullable checks --- .../EtwEventSource.cs | 31 +++++++++---------- 1 file changed, 15 insertions(+), 16 deletions(-) diff --git a/src/WebJobs.Extensions.DurableTask/EtwEventSource.cs b/src/WebJobs.Extensions.DurableTask/EtwEventSource.cs index 77f9bb0e4..019e27a2f 100644 --- a/src/WebJobs.Extensions.DurableTask/EtwEventSource.cs +++ b/src/WebJobs.Extensions.DurableTask/EtwEventSource.cs @@ -1,7 +1,6 @@ // Copyright (c) .NET Foundation. All rights reserved. // Licensed under the MIT License. See LICENSE in the project root for license information. - -using System; +#nullable enable using System.Diagnostics.Tracing; namespace Microsoft.Azure.WebJobs.Extensions.DurableTask @@ -43,7 +42,7 @@ public void FunctionStarting( string FunctionName, int TaskEventId, string InstanceId, - string Input, + string? Input, string FunctionType, string ExtensionVersion, bool IsReplay) @@ -88,7 +87,7 @@ public void ExternalEventRaised( string FunctionName, string InstanceId, string EventName, - string Input, + string? Input, string FunctionType, string ExtensionVersion, bool IsReplay) @@ -104,7 +103,7 @@ public void FunctionCompleted( string FunctionName, int TaskEventId, string InstanceId, - string Output, + string? Output, bool ContinuedAsNew, string FunctionType, string ExtensionVersion, @@ -204,7 +203,7 @@ public void EventGridNotificationException( string SlotName, string FunctionName, FunctionState FunctionState, - string Version, + string? Version, string InstanceId, string Details, string Reason, @@ -222,8 +221,8 @@ public void ExtensionInformationalEvent( string TaskHub, string AppName, string SlotName, - string FunctionName, - string InstanceId, + string? FunctionName, + string? InstanceId, string Details, string ExtensionVersion) { @@ -235,8 +234,8 @@ public void ExtensionWarningEvent( string TaskHub, string AppName, string SlotName, - string FunctionName, - string InstanceId, + string? FunctionName, + string? InstanceId, string Details, string ExtensionVersion) { @@ -265,7 +264,7 @@ public void FunctionRewound( string SlotName, string FunctionName, string InstanceId, - string Reason, + string? Reason, string FunctionType, string ExtensionVersion, bool IsReplay) @@ -297,7 +296,7 @@ public void EntityResponseReceived( string FunctionName, string InstanceId, string OperationId, - string Result, + string? Result, string FunctionType, string ExtensionVersion, bool IsReplay) @@ -313,7 +312,7 @@ public void EntityLockAcquired( string FunctionName, string InstanceId, string RequestingInstanceId, - string RequestingExecutionId, + string? RequestingExecutionId, string RequestId, string FunctionType, string ExtensionVersion, @@ -347,8 +346,8 @@ public void OperationCompleted( string InstanceId, string OperationId, string OperationName, - string Input, - string Output, + string? Input, + string? Output, double Duration, string FunctionType, string ExtensionVersion, @@ -366,7 +365,7 @@ public void OperationFailed( string InstanceId, string OperationId, string OperationName, - string Input, + string? Input, string Exception, double Duration, string FunctionType, From 95bcd87541f17fce071268854a6ff0ae02f32441 Mon Sep 17 00:00:00 2001 From: David Justo Date: Tue, 11 Jun 2024 10:17:39 -0700 Subject: [PATCH 09/30] add nullable checks in E2ETraceHelper --- src/WebJobs.Extensions.DurableTask/EndToEndTraceHelper.cs | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) diff --git a/src/WebJobs.Extensions.DurableTask/EndToEndTraceHelper.cs b/src/WebJobs.Extensions.DurableTask/EndToEndTraceHelper.cs index 4304db7a7..6163b235c 100644 --- a/src/WebJobs.Extensions.DurableTask/EndToEndTraceHelper.cs +++ b/src/WebJobs.Extensions.DurableTask/EndToEndTraceHelper.cs @@ -8,14 +8,16 @@ using DurableTask.Core.Exceptions; using Microsoft.Extensions.Logging; +#nullable enable + namespace Microsoft.Azure.WebJobs.Extensions.DurableTask { internal class EndToEndTraceHelper { private static readonly string ExtensionVersion = FileVersionInfo.GetVersionInfo(typeof(DurableTaskExtension).Assembly.Location).FileVersion; - private static string appName; - private static string slotName; + private static string? appName; + private static string? slotName; private readonly ILogger logger; private readonly bool traceReplayEvents; @@ -125,7 +127,6 @@ public void FunctionScheduled( LocalAppName, LocalSlotName, ExtensionVersion, this.sequenceNumber++); } } -#nullable enable public void FunctionStarting( string hubName, @@ -167,7 +168,6 @@ public void FunctionStarting( LocalAppName, LocalSlotName, ExtensionVersion, this.sequenceNumber++, taskEventId); } } -#nullable disable public void FunctionAwaited( string hubName, From dbd62d239bf2cb30400b0b3d791b9e080b775324 Mon Sep 17 00:00:00 2001 From: David Justo Date: Tue, 11 Jun 2024 10:18:34 -0700 Subject: [PATCH 10/30] remove whitespace --- src/WebJobs.Extensions.DurableTask/EndToEndTraceHelper.cs | 1 - 1 file changed, 1 deletion(-) diff --git a/src/WebJobs.Extensions.DurableTask/EndToEndTraceHelper.cs b/src/WebJobs.Extensions.DurableTask/EndToEndTraceHelper.cs index 6163b235c..bc7e12d5f 100644 --- a/src/WebJobs.Extensions.DurableTask/EndToEndTraceHelper.cs +++ b/src/WebJobs.Extensions.DurableTask/EndToEndTraceHelper.cs @@ -9,7 +9,6 @@ using Microsoft.Extensions.Logging; #nullable enable - namespace Microsoft.Azure.WebJobs.Extensions.DurableTask { internal class EndToEndTraceHelper From 1ea40e3c2676f386d30a5d26ac48954d96e4b499 Mon Sep 17 00:00:00 2001 From: David Justo Date: Tue, 11 Jun 2024 10:35:59 -0700 Subject: [PATCH 11/30] add nullability checks --- .../EndToEndTraceHelper.cs | 14 ++++++-------- 1 file changed, 6 insertions(+), 8 deletions(-) diff --git a/src/WebJobs.Extensions.DurableTask/EndToEndTraceHelper.cs b/src/WebJobs.Extensions.DurableTask/EndToEndTraceHelper.cs index bc7e12d5f..2628f2cd7 100644 --- a/src/WebJobs.Extensions.DurableTask/EndToEndTraceHelper.cs +++ b/src/WebJobs.Extensions.DurableTask/EndToEndTraceHelper.cs @@ -136,7 +136,6 @@ public void FunctionStarting( bool isReplay, int taskEventId = -1) { - if (this.shouldCensor) { input = ""; @@ -227,7 +226,7 @@ public void FunctionCompleted( string hubName, string functionName, string instanceId, - string output, + string? output, bool continuedAsNew, FunctionType functionType, bool isReplay, @@ -389,25 +388,25 @@ public void FunctionFailed( string hubName, string functionName, string instanceId, - Exception exception, + Exception? exception, FunctionType functionType, bool isReplay, int taskEventId = -1) { - - string reason = exception.Message; + string reason = exception != null ? exception.Message : string.Empty; if (exception is OrchestrationFailureException orchestrationFailureException) { reason = orchestrationFailureException.Details; } - string sanitizedReason = $"{exception.GetType().FullName}\n{exception.StackTrace}"; + string sanitizedReason = exception != null ? $"{exception.GetType().FullName}\n{exception.StackTrace}" : string.Empty; if (isReplay) { - reason = $"(replayed {exception.GetType().Name})"; + reason = $"(replayed {exception?.GetType().Name})"; sanitizedReason = reason; } + this.FunctionFailed(hubName, functionName, instanceId, reason, sanitizedReason, functionType, isReplay, taskEventId); } @@ -421,7 +420,6 @@ public void FunctionFailed( bool isReplay, int taskEventId = -1) { - if (this.ShouldLogEvent(isReplay)) { EtwEventSource.Instance.FunctionFailed( From a43292c2e17cabd3f0b9192e2cc9ec9fd9025355 Mon Sep 17 00:00:00 2001 From: David Justo Date: Tue, 11 Jun 2024 10:48:25 -0700 Subject: [PATCH 12/30] clean up --- .../Listener/TaskActivityShim.cs | 7 ++++--- .../Listener/WrappedFunctionResult.cs | 5 +++-- .../WebJobs.Extensions.DurableTask.csproj | 6 ++++-- 3 files changed, 11 insertions(+), 7 deletions(-) diff --git a/src/WebJobs.Extensions.DurableTask/Listener/TaskActivityShim.cs b/src/WebJobs.Extensions.DurableTask/Listener/TaskActivityShim.cs index 2e356d66f..128ed4c44 100644 --- a/src/WebJobs.Extensions.DurableTask/Listener/TaskActivityShim.cs +++ b/src/WebJobs.Extensions.DurableTask/Listener/TaskActivityShim.cs @@ -10,6 +10,7 @@ using Microsoft.Azure.WebJobs.Host; using Microsoft.Azure.WebJobs.Host.Executors; +#nullable enable namespace Microsoft.Azure.WebJobs.Extensions.DurableTask { /// @@ -100,7 +101,7 @@ public override async Task RunAsync(TaskContext context, string rawInput case WrappedFunctionResult.FunctionResultStatus.FunctionTimeoutError: // Flow the original activity function exception to the orchestration // without the outer FunctionInvocationException. - Exception exceptionToReport = StripFunctionInvocationException(result.Exception); + Exception? exceptionToReport = StripFunctionInvocationException(result.Exception); if (OutOfProcExceptionHelpers.TryGetExceptionWithFriendlyMessage( exceptionToReport, @@ -119,7 +120,7 @@ public override async Task RunAsync(TaskContext context, string rawInput taskEventId: this.taskEventId); throw new TaskFailureException( - $"Activity function '{this.activityName}' failed: {exceptionToReport.Message}", + $"Activity function '{this.activityName}' failed: {exceptionToReport!.Message}", Utils.SerializeCause(exceptionToReport, this.config.ErrorDataConverter)); default: // we throw a TaskFailureException to ensure deserialization is possible. @@ -143,7 +144,7 @@ internal void SetTaskEventId(int taskEventId) this.taskEventId = taskEventId; } - private static Exception StripFunctionInvocationException(Exception e) + private static Exception? StripFunctionInvocationException(Exception? e) { var infrastructureException = e as FunctionInvocationException; if (infrastructureException?.InnerException != null) diff --git a/src/WebJobs.Extensions.DurableTask/Listener/WrappedFunctionResult.cs b/src/WebJobs.Extensions.DurableTask/Listener/WrappedFunctionResult.cs index fade92f13..f758179d2 100644 --- a/src/WebJobs.Extensions.DurableTask/Listener/WrappedFunctionResult.cs +++ b/src/WebJobs.Extensions.DurableTask/Listener/WrappedFunctionResult.cs @@ -3,13 +3,14 @@ using System; +#nullable enable namespace Microsoft.Azure.WebJobs.Extensions.DurableTask.Listener { internal class WrappedFunctionResult { private WrappedFunctionResult( FunctionResultStatus status, - Exception ex) + Exception? ex) { this.Exception = ex; this.ExecutionStatus = status; @@ -24,7 +25,7 @@ internal enum FunctionResultStatus FunctionsHostStoppingError = 4, // host was shutting down; treated as a functions runtime error } - internal Exception Exception { get; } + internal Exception? Exception { get; } internal FunctionResultStatus ExecutionStatus { get; } diff --git a/src/WebJobs.Extensions.DurableTask/WebJobs.Extensions.DurableTask.csproj b/src/WebJobs.Extensions.DurableTask/WebJobs.Extensions.DurableTask.csproj index 256aea537..823e2f182 100644 --- a/src/WebJobs.Extensions.DurableTask/WebJobs.Extensions.DurableTask.csproj +++ b/src/WebJobs.Extensions.DurableTask/WebJobs.Extensions.DurableTask.csproj @@ -57,7 +57,9 @@ - + + NU1903;NU1902 + @@ -96,7 +98,7 @@ $(DefineConstants);FUNCTIONS_V2_OR_GREATER;FUNCTIONS_V3_OR_GREATER - + From e4fab7a8b4c3be995e9a0f128ff065b044728346 Mon Sep 17 00:00:00 2001 From: David Justo Date: Tue, 11 Jun 2024 12:33:13 -0700 Subject: [PATCH 13/30] refactorings --- .../EndToEndTraceHelper.cs | 126 +++++++----------- 1 file changed, 51 insertions(+), 75 deletions(-) diff --git a/src/WebJobs.Extensions.DurableTask/EndToEndTraceHelper.cs b/src/WebJobs.Extensions.DurableTask/EndToEndTraceHelper.cs index 2628f2cd7..a53120015 100644 --- a/src/WebJobs.Extensions.DurableTask/EndToEndTraceHelper.cs +++ b/src/WebJobs.Extensions.DurableTask/EndToEndTraceHelper.cs @@ -20,15 +20,15 @@ internal class EndToEndTraceHelper private readonly ILogger logger; private readonly bool traceReplayEvents; - private readonly bool shouldCensor; + private readonly bool shouldTraceRawData; private long sequenceNumber; - public EndToEndTraceHelper(ILogger logger, bool traceReplayEvents, bool shouldCensor = false) + public EndToEndTraceHelper(ILogger logger, bool traceReplayEvents, bool shouldTraceRawData = false) { this.logger = logger ?? throw new ArgumentNullException(nameof(logger)); this.traceReplayEvents = traceReplayEvents; - this.shouldCensor = shouldCensor; + this.shouldTraceRawData = shouldTraceRawData; } public static string LocalAppName @@ -59,6 +59,22 @@ public static string LocalSlotName #pragma warning disable SA1117 // Parameters should be on same line or separate lines + private string Sanitize(string? rawPayload, out string iloggerPayload, bool isReplay = false) + { + if (isReplay) + { + iloggerPayload = "(replay)"; + return "(replay)"; + } + + string payload = rawPayload ?? string.Empty; + int numCharacters = payload.Length; + string sanitizedPayload = $"(Redacted {numCharacters} characters)"; + + iloggerPayload = this.shouldTraceRawData ? payload : sanitizedPayload; + return sanitizedPayload; + } + public void ExtensionInformationalEvent( string hubName, string instanceId, @@ -136,15 +152,7 @@ public void FunctionStarting( bool isReplay, int taskEventId = -1) { - if (this.shouldCensor) - { - input = ""; - } - - if (isReplay) - { - input = "(replay)"; - } + string sanitizedInput = this.Sanitize(input, out string loggerInput, isReplay: isReplay); if (this.ShouldLogEvent(isReplay)) { @@ -155,14 +163,14 @@ public void FunctionStarting( functionName, taskEventId, instanceId, - input, + sanitizedInput, functionType.ToString(), ExtensionVersion, isReplay); this.logger.LogInformation( "{instanceId}: Function '{functionName} ({functionType})' started. IsReplay: {isReplay}. Input: {input}. State: {state}. RuntimeStatus: {runtimeStatus}. HubName: {hubName}. AppName: {appName}. SlotName: {slotName}. ExtensionVersion: {extensionVersion}. SequenceNumber: {sequenceNumber}. TaskEventId: {taskEventId}", - instanceId, functionName, functionType, isReplay, input, FunctionState.Started, OrchestrationRuntimeStatus.Running, hubName, + instanceId, functionName, functionType, isReplay, loggerInput, FunctionState.Started, OrchestrationRuntimeStatus.Running, hubName, LocalAppName, LocalSlotName, ExtensionVersion, this.sequenceNumber++, taskEventId); } } @@ -232,15 +240,7 @@ public void FunctionCompleted( bool isReplay, int taskEventId = -1) { - if (this.shouldCensor) - { - output = ""; - } - - if (isReplay) - { - output = "(replay)"; - } + string sanitizedOutput = this.Sanitize(output, out string loggerOutput, isReplay: isReplay); if (this.ShouldLogEvent(isReplay)) { @@ -251,7 +251,7 @@ public void FunctionCompleted( functionName, taskEventId, instanceId, - output, + sanitizedOutput, continuedAsNew, functionType.ToString(), ExtensionVersion, @@ -259,7 +259,7 @@ public void FunctionCompleted( this.logger.LogInformation( "{instanceId}: Function '{functionName} ({functionType})' completed. ContinuedAsNew: {continuedAsNew}. IsReplay: {isReplay}. Output: {output}. State: {state}. RuntimeStatus: {runtimeStatus}. HubName: {hubName}. AppName: {appName}. SlotName: {slotName}. ExtensionVersion: {extensionVersion}. SequenceNumber: {sequenceNumber}. TaskEventId: {taskEventId}", - instanceId, functionName, functionType, continuedAsNew, isReplay, output, FunctionState.Completed, OrchestrationRuntimeStatus.Completed, hubName, + instanceId, functionName, functionType, continuedAsNew, isReplay, loggerOutput, FunctionState.Completed, OrchestrationRuntimeStatus.Completed, hubName, LocalAppName, LocalSlotName, ExtensionVersion, this.sequenceNumber++, taskEventId); } } @@ -270,10 +270,7 @@ public void FunctionTerminated( string instanceId, string reason) { - if (this.shouldCensor) - { - reason = ""; - } + string sanitizedReason = this.Sanitize(reason, out string loggerReason); FunctionType functionType = FunctionType.Orchestrator; @@ -283,14 +280,14 @@ public void FunctionTerminated( LocalSlotName, functionName, instanceId, - reason, + sanitizedReason, functionType.ToString(), ExtensionVersion, IsReplay: false); this.logger.LogWarning( "{instanceId}: Function '{functionName} ({functionType})' was terminated. Reason: {reason}. State: {state}. RuntimeStatus: {runtimeStatus}. HubName: {hubName}. AppName: {appName}. SlotName: {slotName}. ExtensionVersion: {extensionVersion}. SequenceNumber: {sequenceNumber}.", - instanceId, functionName, functionType, reason, FunctionState.Terminated, OrchestrationRuntimeStatus.Terminated, hubName, + instanceId, functionName, functionType, loggerReason, FunctionState.Terminated, OrchestrationRuntimeStatus.Terminated, hubName, LocalAppName, LocalSlotName, ExtensionVersion, this.sequenceNumber++); } @@ -300,10 +297,7 @@ public void SuspendingOrchestration( string instanceId, string reason) { - if (this.shouldCensor) - { - reason = ""; - } + string sanitizedReason = this.Sanitize(reason, out string loggerReason); FunctionType functionType = FunctionType.Orchestrator; @@ -313,14 +307,14 @@ public void SuspendingOrchestration( LocalSlotName, functionName, instanceId, - reason, + sanitizedReason, functionType.ToString(), ExtensionVersion, IsReplay: false); this.logger.LogInformation( "{instanceId}: Suspending function '{functionName} ({functionType})'. Reason: {reason}. State: {state}. RuntimeStatus: {runtimeStatus}. HubName: {hubName}. AppName: {appName}. SlotName: {slotName}. ExtensionVersion: {extensionVersion}. SequenceNumber: {sequenceNumber}.", - instanceId, functionName, functionType, reason, FunctionState.Suspended, OrchestrationRuntimeStatus.Suspended, hubName, + instanceId, functionName, functionType, loggerReason, FunctionState.Suspended, OrchestrationRuntimeStatus.Suspended, hubName, LocalAppName, LocalSlotName, ExtensionVersion, this.sequenceNumber++); } @@ -330,10 +324,7 @@ public void ResumingOrchestration( string instanceId, string reason) { - if (this.shouldCensor) - { - reason = ""; - } + string sanitizedReason = this.Sanitize(reason, out string loggerReason); FunctionType functionType = FunctionType.Orchestrator; @@ -343,14 +334,14 @@ public void ResumingOrchestration( LocalSlotName, functionName, instanceId, - reason, + sanitizedReason, functionType.ToString(), ExtensionVersion, IsReplay: false); this.logger.LogInformation( "{instanceId}: Resuming function '{functionName} ({functionType})'. Reason: {reason}. State: {state}. RuntimeStatus: {runtimeStatus}. HubName: {hubName}. AppName: {appName}. SlotName: {slotName}. ExtensionVersion: {extensionVersion}. SequenceNumber: {sequenceNumber}.", - instanceId, functionName, functionType, reason, FunctionState.Scheduled, OrchestrationRuntimeStatus.Running, hubName, + instanceId, functionName, functionType, loggerReason, FunctionState.Scheduled, OrchestrationRuntimeStatus.Running, hubName, LocalAppName, LocalSlotName, ExtensionVersion, this.sequenceNumber++); } @@ -360,10 +351,7 @@ public void FunctionRewound( string instanceId, string reason) { - if (this.shouldCensor) - { - reason = ""; - } + string sanitizedReason = this.Sanitize(reason, out string loggerReason); FunctionType functionType = FunctionType.Orchestrator; @@ -373,14 +361,14 @@ public void FunctionRewound( LocalSlotName, functionName, instanceId, - reason, + sanitizedReason, functionType.ToString(), ExtensionVersion, IsReplay: false); this.logger.LogWarning( "{instanceId}: Function '{functionName} ({functionType})' was rewound. Reason: {reason}. State: {state}. HubName: {hubName}. AppName: {appName}. SlotName: {slotName}. ExtensionVersion: {extensionVersion}. SequenceNumber: {sequenceNumber}.", - instanceId, functionName, functionType, reason, FunctionState.Rewound, hubName, + instanceId, functionName, functionType, loggerReason, FunctionState.Rewound, hubName, LocalAppName, LocalSlotName, ExtensionVersion, this.sequenceNumber++); } @@ -476,11 +464,8 @@ public void OperationCompleted( double duration, bool isReplay) { - if (this.shouldCensor) - { - input = ""; - output = ""; - } + string sanitizedInput = this.Sanitize(input, out string loggerInput); + string sanitizedOutput = this.Sanitize(output, out string loggerOutput); if (this.ShouldLogEvent(isReplay)) { @@ -492,8 +477,8 @@ public void OperationCompleted( instanceId, operationId, operationName, - input, - output, + sanitizedInput, + sanitizedOutput, duration, FunctionType.Entity.ToString(), ExtensionVersion, @@ -501,7 +486,7 @@ public void OperationCompleted( this.logger.LogInformation( "{instanceId}: Function '{functionName} ({functionType})' completed '{operationName}' operation {operationId} in {duration}ms. IsReplay: {isReplay}. Input: {input}. Output: {output}. HubName: {hubName}. AppName: {appName}. SlotName: {slotName}. ExtensionVersion: {extensionVersion}. SequenceNumber: {sequenceNumber}.", - instanceId, functionName, FunctionType.Entity, operationName, operationId, duration, isReplay, input, output, + instanceId, functionName, FunctionType.Entity, operationName, operationId, duration, isReplay, loggerInput, loggerOutput, hubName, LocalAppName, LocalSlotName, ExtensionVersion, this.sequenceNumber++); } } @@ -537,11 +522,8 @@ public void OperationFailed( double duration, bool isReplay) { - if (this.shouldCensor) - { - input = ""; - exception = ""; - } + string sanitizedInput = this.Sanitize(input, out string loggerInput); + string sanitizedException = this.Sanitize(exception, out string loggerException); if (this.ShouldLogEvent(isReplay)) { @@ -553,8 +535,8 @@ public void OperationFailed( instanceId, operationId, operationName, - input, - exception, + sanitizedInput, + sanitizedException, duration, FunctionType.Entity.ToString(), ExtensionVersion, @@ -562,7 +544,7 @@ public void OperationFailed( this.logger.LogError( "{instanceId}: Function '{functionName} ({functionType})' failed '{operationName}' operation {operationId} after {duration}ms with exception {exception}. Input: {input}. IsReplay: {isReplay}. HubName: {hubName}. AppName: {appName}. SlotName: {slotName}. ExtensionVersion: {extensionVersion}. SequenceNumber: {sequenceNumber}.", - instanceId, functionName, FunctionType.Entity, operationName, operationId, duration, exception, input, isReplay, hubName, + instanceId, functionName, FunctionType.Entity, operationName, operationId, duration, loggerException, loggerInput, isReplay, hubName, LocalAppName, LocalSlotName, ExtensionVersion, this.sequenceNumber++); } } @@ -575,10 +557,7 @@ public void ExternalEventRaised( string input, bool isReplay) { - if (this.shouldCensor) - { - input = ""; - } + string sanitizedInput = this.Sanitize(input, out string _); if (this.ShouldLogEvent(isReplay)) { @@ -591,7 +570,7 @@ public void ExternalEventRaised( functionName, instanceId, eventName, - input, + sanitizedInput, functionType.ToString(), ExtensionVersion, isReplay); @@ -697,10 +676,7 @@ public void EntityResponseReceived( string result, bool isReplay) { - if (this.shouldCensor) - { - result = ""; - } + string sanitizedResult = this.Sanitize(result, out string _); if (this.ShouldLogEvent(isReplay)) { @@ -711,7 +687,7 @@ public void EntityResponseReceived( functionName, instanceId, operationId, - result, + sanitizedResult, functionType.ToString(), ExtensionVersion, isReplay); From 39f400e5044313e6af1b002d5729affd325b6376 Mon Sep 17 00:00:00 2001 From: David Justo Date: Tue, 11 Jun 2024 12:55:05 -0700 Subject: [PATCH 14/30] refactorings --- .../EndToEndTraceHelper.cs | 87 +++++++++++-------- 1 file changed, 52 insertions(+), 35 deletions(-) diff --git a/src/WebJobs.Extensions.DurableTask/EndToEndTraceHelper.cs b/src/WebJobs.Extensions.DurableTask/EndToEndTraceHelper.cs index a53120015..7ddb58257 100644 --- a/src/WebJobs.Extensions.DurableTask/EndToEndTraceHelper.cs +++ b/src/WebJobs.Extensions.DurableTask/EndToEndTraceHelper.cs @@ -59,7 +59,7 @@ public static string LocalSlotName #pragma warning disable SA1117 // Parameters should be on same line or separate lines - private string Sanitize(string? rawPayload, out string iloggerPayload, bool isReplay = false) + private string SanitizeString(string? rawPayload, out string iloggerPayload, bool isReplay = false) { if (isReplay) { @@ -75,6 +75,25 @@ private string Sanitize(string? rawPayload, out string iloggerPayload, bool isRe return sanitizedPayload; } + private string SanitizeException(Exception? exception, out string iloggerExceptionString, bool isReplay = false) + { + if (isReplay) + { + iloggerExceptionString = "(replay)"; + return "(replay)"; + } + + string exceptionString = exception != null ? exception.Message : string.Empty; + if (exception is OrchestrationFailureException orchestrationFailureException) + { + exceptionString = orchestrationFailureException.Details; + } + + string sanitizedString = exception != null ? $"{exception.GetType().FullName}\n{exception.StackTrace}" : string.Empty; + iloggerExceptionString = this.shouldTraceRawData ? exceptionString : sanitizedString; + return sanitizedString; + } + public void ExtensionInformationalEvent( string hubName, string instanceId, @@ -152,7 +171,7 @@ public void FunctionStarting( bool isReplay, int taskEventId = -1) { - string sanitizedInput = this.Sanitize(input, out string loggerInput, isReplay: isReplay); + string sanitizedInput = this.SanitizeString(input, out string loggerInput, isReplay: isReplay); if (this.ShouldLogEvent(isReplay)) { @@ -240,7 +259,7 @@ public void FunctionCompleted( bool isReplay, int taskEventId = -1) { - string sanitizedOutput = this.Sanitize(output, out string loggerOutput, isReplay: isReplay); + string sanitizedOutput = this.SanitizeString(output, out string loggerOutput, isReplay: isReplay); if (this.ShouldLogEvent(isReplay)) { @@ -270,7 +289,7 @@ public void FunctionTerminated( string instanceId, string reason) { - string sanitizedReason = this.Sanitize(reason, out string loggerReason); + string sanitizedReason = this.SanitizeString(reason, out string loggerReason); FunctionType functionType = FunctionType.Orchestrator; @@ -297,7 +316,7 @@ public void SuspendingOrchestration( string instanceId, string reason) { - string sanitizedReason = this.Sanitize(reason, out string loggerReason); + string sanitizedReason = this.SanitizeString(reason, out string loggerReason); FunctionType functionType = FunctionType.Orchestrator; @@ -324,7 +343,7 @@ public void ResumingOrchestration( string instanceId, string reason) { - string sanitizedReason = this.Sanitize(reason, out string loggerReason); + string sanitizedReason = this.SanitizeString(reason, out string loggerReason); FunctionType functionType = FunctionType.Orchestrator; @@ -351,7 +370,7 @@ public void FunctionRewound( string instanceId, string reason) { - string sanitizedReason = this.Sanitize(reason, out string loggerReason); + string sanitizedReason = this.SanitizeString(reason, out string loggerReason); FunctionType functionType = FunctionType.Orchestrator; @@ -381,21 +400,8 @@ public void FunctionFailed( bool isReplay, int taskEventId = -1) { - string reason = exception != null ? exception.Message : string.Empty; - if (exception is OrchestrationFailureException orchestrationFailureException) - { - reason = orchestrationFailureException.Details; - } - - string sanitizedReason = exception != null ? $"{exception.GetType().FullName}\n{exception.StackTrace}" : string.Empty; - - if (isReplay) - { - reason = $"(replayed {exception?.GetType().Name})"; - sanitizedReason = reason; - } - - this.FunctionFailed(hubName, functionName, instanceId, reason, sanitizedReason, functionType, isReplay, taskEventId); + string sanitizedReason = this.SanitizeException(exception, out string loggerReason, isReplay); + this.FunctionFailed(hubName, functionName, instanceId, loggerReason, sanitizedReason, functionType, isReplay, taskEventId); } public void FunctionFailed( @@ -464,8 +470,8 @@ public void OperationCompleted( double duration, bool isReplay) { - string sanitizedInput = this.Sanitize(input, out string loggerInput); - string sanitizedOutput = this.Sanitize(output, out string loggerOutput); + string sanitizedInput = this.SanitizeString(input, out string loggerInput); + string sanitizedOutput = this.SanitizeString(output, out string loggerOutput); if (this.ShouldLogEvent(isReplay)) { @@ -502,13 +508,9 @@ public void OperationFailed( double duration, bool isReplay) { - string exceptionString = exception.ToString(); - if (isReplay) - { - exceptionString = $"(replayed {exception.GetType().Name})"; - } - - this.OperationFailed(hubName, functionName, instanceId, operationId, operationName, input, exceptionString, duration, isReplay); + string sanitizedInput = this.SanitizeString(input, out string loggerInput); + string sanitizedException = this.SanitizeException(exception, out string loggerException, isReplay); + this.OperationFailed(hubName, functionName, instanceId, operationId, operationName, sanitizedInput, loggerInput, sanitizedException, loggerException, duration, isReplay); } public void OperationFailed( @@ -522,9 +524,24 @@ public void OperationFailed( double duration, bool isReplay) { - string sanitizedInput = this.Sanitize(input, out string loggerInput); - string sanitizedException = this.Sanitize(exception, out string loggerException); + string sanitizedInput = this.SanitizeString(input, out string loggerInput); + string sanitizedException = this.SanitizeString(exception, out string loggerException); + this.OperationFailed(hubName, functionName, instanceId, operationId, operationName, sanitizedInput, loggerInput, sanitizedException, loggerException, duration, isReplay); + } + private void OperationFailed( + string hubName, + string functionName, + string instanceId, + string operationId, + string operationName, + string sanitizedInput, + string loggerInput, + string sanitizedException, + string loggerException, + double duration, + bool isReplay) + { if (this.ShouldLogEvent(isReplay)) { EtwEventSource.Instance.OperationFailed( @@ -557,7 +574,7 @@ public void ExternalEventRaised( string input, bool isReplay) { - string sanitizedInput = this.Sanitize(input, out string _); + string sanitizedInput = this.SanitizeString(input, out string _); if (this.ShouldLogEvent(isReplay)) { @@ -676,7 +693,7 @@ public void EntityResponseReceived( string result, bool isReplay) { - string sanitizedResult = this.Sanitize(result, out string _); + string sanitizedResult = this.SanitizeString(result, out string _); if (this.ShouldLogEvent(isReplay)) { From 80f6a09d26f8afd831c5ed31e3e5efe95015a39e Mon Sep 17 00:00:00 2001 From: David Justo Date: Tue, 11 Jun 2024 13:16:53 -0700 Subject: [PATCH 15/30] add comments in csproj --- .../WebJobs.Extensions.DurableTask.csproj | 7 ++++--- 1 file changed, 4 insertions(+), 3 deletions(-) diff --git a/src/WebJobs.Extensions.DurableTask/WebJobs.Extensions.DurableTask.csproj b/src/WebJobs.Extensions.DurableTask/WebJobs.Extensions.DurableTask.csproj index 823e2f182..8a15d5459 100644 --- a/src/WebJobs.Extensions.DurableTask/WebJobs.Extensions.DurableTask.csproj +++ b/src/WebJobs.Extensions.DurableTask/WebJobs.Extensions.DurableTask.csproj @@ -58,8 +58,9 @@ - NU1903;NU1902 - + NU1903;NU1902 + @@ -98,7 +99,7 @@ $(DefineConstants);FUNCTIONS_V2_OR_GREATER;FUNCTIONS_V3_OR_GREATER - + From d3103fef862335639bea62f6316e09d88e441930 Mon Sep 17 00:00:00 2001 From: David Justo Date: Wed, 12 Jun 2024 17:40:39 -0700 Subject: [PATCH 16/30] quick test --- src/WebJobs.Extensions.DurableTask/EndToEndTraceHelper.cs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/WebJobs.Extensions.DurableTask/EndToEndTraceHelper.cs b/src/WebJobs.Extensions.DurableTask/EndToEndTraceHelper.cs index 7ddb58257..8852bccf8 100644 --- a/src/WebJobs.Extensions.DurableTask/EndToEndTraceHelper.cs +++ b/src/WebJobs.Extensions.DurableTask/EndToEndTraceHelper.cs @@ -63,7 +63,7 @@ private string SanitizeString(string? rawPayload, out string iloggerPayload, boo { if (isReplay) { - iloggerPayload = "(replay)"; + iloggerPayload = rawPayload; return "(replay)"; } From 1fe4e6786bea5a03dbc6fe15185f1659d746884c Mon Sep 17 00:00:00 2001 From: David Justo Date: Wed, 12 Jun 2024 17:42:38 -0700 Subject: [PATCH 17/30] remove nullable assignment --- src/WebJobs.Extensions.DurableTask/EndToEndTraceHelper.cs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/WebJobs.Extensions.DurableTask/EndToEndTraceHelper.cs b/src/WebJobs.Extensions.DurableTask/EndToEndTraceHelper.cs index 8852bccf8..3fc41c33d 100644 --- a/src/WebJobs.Extensions.DurableTask/EndToEndTraceHelper.cs +++ b/src/WebJobs.Extensions.DurableTask/EndToEndTraceHelper.cs @@ -63,7 +63,7 @@ private string SanitizeString(string? rawPayload, out string iloggerPayload, boo { if (isReplay) { - iloggerPayload = rawPayload; + iloggerPayload = rawPayload ?? "(replay)"; return "(replay)"; } From caf746ebf943dbbe5a2d79f965cf734829879af0 Mon Sep 17 00:00:00 2001 From: David Justo Date: Wed, 12 Jun 2024 17:54:51 -0700 Subject: [PATCH 18/30] small edit --- .../EndToEndTraceHelper.cs | 14 +++++++------- 1 file changed, 7 insertions(+), 7 deletions(-) diff --git a/src/WebJobs.Extensions.DurableTask/EndToEndTraceHelper.cs b/src/WebJobs.Extensions.DurableTask/EndToEndTraceHelper.cs index 3fc41c33d..5d7fdd8e9 100644 --- a/src/WebJobs.Extensions.DurableTask/EndToEndTraceHelper.cs +++ b/src/WebJobs.Extensions.DurableTask/EndToEndTraceHelper.cs @@ -77,13 +77,7 @@ private string SanitizeString(string? rawPayload, out string iloggerPayload, boo private string SanitizeException(Exception? exception, out string iloggerExceptionString, bool isReplay = false) { - if (isReplay) - { - iloggerExceptionString = "(replay)"; - return "(replay)"; - } - - string exceptionString = exception != null ? exception.Message : string.Empty; + string exceptionString = exception != null ? exception.toString() : string.Empty; if (exception is OrchestrationFailureException orchestrationFailureException) { exceptionString = orchestrationFailureException.Details; @@ -91,6 +85,12 @@ private string SanitizeException(Exception? exception, out string iloggerExcepti string sanitizedString = exception != null ? $"{exception.GetType().FullName}\n{exception.StackTrace}" : string.Empty; iloggerExceptionString = this.shouldTraceRawData ? exceptionString : sanitizedString; + + if (isReplay) + { + return "(replay)"; + } + return sanitizedString; } From 10ac5a979800f1afd3d605dbea58bc60585bdb5a Mon Sep 17 00:00:00 2001 From: David Justo Date: Wed, 12 Jun 2024 17:56:58 -0700 Subject: [PATCH 19/30] minor refactor --- src/WebJobs.Extensions.DurableTask/EndToEndTraceHelper.cs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/WebJobs.Extensions.DurableTask/EndToEndTraceHelper.cs b/src/WebJobs.Extensions.DurableTask/EndToEndTraceHelper.cs index 5d7fdd8e9..a87b24369 100644 --- a/src/WebJobs.Extensions.DurableTask/EndToEndTraceHelper.cs +++ b/src/WebJobs.Extensions.DurableTask/EndToEndTraceHelper.cs @@ -77,7 +77,7 @@ private string SanitizeString(string? rawPayload, out string iloggerPayload, boo private string SanitizeException(Exception? exception, out string iloggerExceptionString, bool isReplay = false) { - string exceptionString = exception != null ? exception.toString() : string.Empty; + string exceptionString = exception != null ? exception.ToString() : string.Empty; if (exception is OrchestrationFailureException orchestrationFailureException) { exceptionString = orchestrationFailureException.Details; From 900b1a252729b4d91e728c4b343333278706526a Mon Sep 17 00:00:00 2001 From: David Justo Date: Wed, 12 Jun 2024 18:02:20 -0700 Subject: [PATCH 20/30] remove line --- src/WebJobs.Extensions.DurableTask/EndToEndTraceHelper.cs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/WebJobs.Extensions.DurableTask/EndToEndTraceHelper.cs b/src/WebJobs.Extensions.DurableTask/EndToEndTraceHelper.cs index a87b24369..284eee34e 100644 --- a/src/WebJobs.Extensions.DurableTask/EndToEndTraceHelper.cs +++ b/src/WebJobs.Extensions.DurableTask/EndToEndTraceHelper.cs @@ -85,7 +85,7 @@ private string SanitizeException(Exception? exception, out string iloggerExcepti string sanitizedString = exception != null ? $"{exception.GetType().FullName}\n{exception.StackTrace}" : string.Empty; iloggerExceptionString = this.shouldTraceRawData ? exceptionString : sanitizedString; - + if (isReplay) { return "(replay)"; From 032f566eb82852a6666c10518a3c631e1ca878a7 Mon Sep 17 00:00:00 2001 From: David Justo Date: Wed, 12 Jun 2024 18:04:49 -0700 Subject: [PATCH 21/30] remove line --- src/WebJobs.Extensions.DurableTask/EndToEndTraceHelper.cs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/WebJobs.Extensions.DurableTask/EndToEndTraceHelper.cs b/src/WebJobs.Extensions.DurableTask/EndToEndTraceHelper.cs index 284eee34e..7f8ac149d 100644 --- a/src/WebJobs.Extensions.DurableTask/EndToEndTraceHelper.cs +++ b/src/WebJobs.Extensions.DurableTask/EndToEndTraceHelper.cs @@ -90,7 +90,7 @@ private string SanitizeException(Exception? exception, out string iloggerExcepti { return "(replay)"; } - + return sanitizedString; } From f31cad9c62e2e272f1087ab098f3db7e82e7a1de Mon Sep 17 00:00:00 2001 From: David Justo Date: Wed, 12 Jun 2024 18:27:14 -0700 Subject: [PATCH 22/30] null string handling --- src/WebJobs.Extensions.DurableTask/EndToEndTraceHelper.cs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/WebJobs.Extensions.DurableTask/EndToEndTraceHelper.cs b/src/WebJobs.Extensions.DurableTask/EndToEndTraceHelper.cs index 7f8ac149d..88783a86a 100644 --- a/src/WebJobs.Extensions.DurableTask/EndToEndTraceHelper.cs +++ b/src/WebJobs.Extensions.DurableTask/EndToEndTraceHelper.cs @@ -67,7 +67,7 @@ private string SanitizeString(string? rawPayload, out string iloggerPayload, boo return "(replay)"; } - string payload = rawPayload ?? string.Empty; + string payload = rawPayload ?? "(null)"; int numCharacters = payload.Length; string sanitizedPayload = $"(Redacted {numCharacters} characters)"; From 43f63fc330a5e19723e9273d2196f3e8a5564f45 Mon Sep 17 00:00:00 2001 From: David Justo Date: Mon, 17 Jun 2024 13:14:46 -0700 Subject: [PATCH 23/30] apply feedback --- .../DurableTaskExtension.cs | 29 ------------ .../EndToEndTraceHelper.cs | 46 +++++++++---------- .../Listener/TaskEntityShim.cs | 2 +- 3 files changed, 24 insertions(+), 53 deletions(-) diff --git a/src/WebJobs.Extensions.DurableTask/DurableTaskExtension.cs b/src/WebJobs.Extensions.DurableTask/DurableTaskExtension.cs index fdf9096cf..937b236ea 100644 --- a/src/WebJobs.Extensions.DurableTask/DurableTaskExtension.cs +++ b/src/WebJobs.Extensions.DurableTask/DurableTaskExtension.cs @@ -1487,35 +1487,6 @@ bool HasActiveListeners(RegisteredFunctionInfo info) return false; } - internal string GetIntputOutputTrace(string rawInputOutputData) - { - if (this.Options.Tracing.TraceInputsAndOutputs) - { - return rawInputOutputData; - } - else if (rawInputOutputData == null) - { - return "(null)"; - } - else - { - // Azure Storage uses UTF-32 encoding for string payloads - return "(" + Encoding.UTF32.GetByteCount(rawInputOutputData) + " bytes)"; - } - } - - internal string GetExceptionTrace(string rawExceptionData) - { - if (rawExceptionData == null) - { - return "(null)"; - } - else - { - return rawExceptionData; - } - } - /// Task IAsyncConverter.ConvertAsync( HttpRequestMessage request, diff --git a/src/WebJobs.Extensions.DurableTask/EndToEndTraceHelper.cs b/src/WebJobs.Extensions.DurableTask/EndToEndTraceHelper.cs index 88783a86a..3a502e430 100644 --- a/src/WebJobs.Extensions.DurableTask/EndToEndTraceHelper.cs +++ b/src/WebJobs.Extensions.DurableTask/EndToEndTraceHelper.cs @@ -59,23 +59,23 @@ public static string LocalSlotName #pragma warning disable SA1117 // Parameters should be on same line or separate lines - private string SanitizeString(string? rawPayload, out string iloggerPayload, bool isReplay = false) + private void SanitizeString(string? rawPayload, out string iloggerString, out string durableKustoTableString, bool isReplay = false) { if (isReplay) { - iloggerPayload = rawPayload ?? "(replay)"; - return "(replay)"; + iloggerString = rawPayload ?? "(replay)"; + durableKustoTableString = "(replay)"; } string payload = rawPayload ?? "(null)"; int numCharacters = payload.Length; string sanitizedPayload = $"(Redacted {numCharacters} characters)"; - iloggerPayload = this.shouldTraceRawData ? payload : sanitizedPayload; - return sanitizedPayload; + iloggerString = this.shouldTraceRawData ? payload : sanitizedPayload; + durableKustoTableString = sanitizedPayload; } - private string SanitizeException(Exception? exception, out string iloggerExceptionString, bool isReplay = false) + private void SanitizeException(Exception? exception, out string iloggerExceptionString, out string durableKustoTableString, bool isReplay = false) { string exceptionString = exception != null ? exception.ToString() : string.Empty; if (exception is OrchestrationFailureException orchestrationFailureException) @@ -88,10 +88,10 @@ private string SanitizeException(Exception? exception, out string iloggerExcepti if (isReplay) { - return "(replay)"; + durableKustoTableString = "(replay)"; } - return sanitizedString; + durableKustoTableString = sanitizedString; } public void ExtensionInformationalEvent( @@ -171,7 +171,7 @@ public void FunctionStarting( bool isReplay, int taskEventId = -1) { - string sanitizedInput = this.SanitizeString(input, out string loggerInput, isReplay: isReplay); + this.SanitizeString(input, out string loggerInput, out string sanitizedInput, isReplay: isReplay); if (this.ShouldLogEvent(isReplay)) { @@ -259,7 +259,7 @@ public void FunctionCompleted( bool isReplay, int taskEventId = -1) { - string sanitizedOutput = this.SanitizeString(output, out string loggerOutput, isReplay: isReplay); + this.SanitizeString(output, out string loggerOutput, out string sanitizedOutput, isReplay: isReplay); if (this.ShouldLogEvent(isReplay)) { @@ -289,7 +289,7 @@ public void FunctionTerminated( string instanceId, string reason) { - string sanitizedReason = this.SanitizeString(reason, out string loggerReason); + this.SanitizeString(reason, out string loggerReason, out string sanitizedReason); FunctionType functionType = FunctionType.Orchestrator; @@ -316,7 +316,7 @@ public void SuspendingOrchestration( string instanceId, string reason) { - string sanitizedReason = this.SanitizeString(reason, out string loggerReason); + this.SanitizeString(reason, out string loggerReason, out string sanitizedReason); FunctionType functionType = FunctionType.Orchestrator; @@ -343,7 +343,7 @@ public void ResumingOrchestration( string instanceId, string reason) { - string sanitizedReason = this.SanitizeString(reason, out string loggerReason); + this.SanitizeString(reason, out string loggerReason, out string sanitizedReason); FunctionType functionType = FunctionType.Orchestrator; @@ -370,7 +370,7 @@ public void FunctionRewound( string instanceId, string reason) { - string sanitizedReason = this.SanitizeString(reason, out string loggerReason); + this.SanitizeString(reason, out string loggerReason, out string sanitizedReason); FunctionType functionType = FunctionType.Orchestrator; @@ -400,7 +400,7 @@ public void FunctionFailed( bool isReplay, int taskEventId = -1) { - string sanitizedReason = this.SanitizeException(exception, out string loggerReason, isReplay); + this.SanitizeException(exception, out string loggerReason, out string sanitizedReason, isReplay); this.FunctionFailed(hubName, functionName, instanceId, loggerReason, sanitizedReason, functionType, isReplay, taskEventId); } @@ -470,8 +470,8 @@ public void OperationCompleted( double duration, bool isReplay) { - string sanitizedInput = this.SanitizeString(input, out string loggerInput); - string sanitizedOutput = this.SanitizeString(output, out string loggerOutput); + this.SanitizeString(input, out string loggerInput, out string sanitizedInput); + this.SanitizeString(output, out string loggerOutput, out string sanitizedOutput); if (this.ShouldLogEvent(isReplay)) { @@ -508,8 +508,8 @@ public void OperationFailed( double duration, bool isReplay) { - string sanitizedInput = this.SanitizeString(input, out string loggerInput); - string sanitizedException = this.SanitizeException(exception, out string loggerException, isReplay); + this.SanitizeString(input, out string loggerInput, out string sanitizedInput); + this.SanitizeException(exception, out string loggerException, out string sanitizedException, isReplay); this.OperationFailed(hubName, functionName, instanceId, operationId, operationName, sanitizedInput, loggerInput, sanitizedException, loggerException, duration, isReplay); } @@ -524,8 +524,8 @@ public void OperationFailed( double duration, bool isReplay) { - string sanitizedInput = this.SanitizeString(input, out string loggerInput); - string sanitizedException = this.SanitizeString(exception, out string loggerException); + this.SanitizeString(input, out string loggerInput, out string sanitizedInput); + this.SanitizeString(exception, out string loggerException, out string sanitizedException); this.OperationFailed(hubName, functionName, instanceId, operationId, operationName, sanitizedInput, loggerInput, sanitizedException, loggerException, duration, isReplay); } @@ -574,7 +574,7 @@ public void ExternalEventRaised( string input, bool isReplay) { - string sanitizedInput = this.SanitizeString(input, out string _); + this.SanitizeString(input, out string _, out string sanitizedInput); if (this.ShouldLogEvent(isReplay)) { @@ -693,7 +693,7 @@ public void EntityResponseReceived( string result, bool isReplay) { - string sanitizedResult = this.SanitizeString(result, out string _); + this.SanitizeString(result, out string _, out string sanitizedResult); if (this.ShouldLogEvent(isReplay)) { diff --git a/src/WebJobs.Extensions.DurableTask/Listener/TaskEntityShim.cs b/src/WebJobs.Extensions.DurableTask/Listener/TaskEntityShim.cs index 975e7b640..648a86731 100644 --- a/src/WebJobs.Extensions.DurableTask/Listener/TaskEntityShim.cs +++ b/src/WebJobs.Extensions.DurableTask/Listener/TaskEntityShim.cs @@ -546,7 +546,7 @@ private async Task ProcessOperationRequestAsync(RequestMessage request) this.context.InstanceId, request.Id.ToString(), request.Operation, - this.Config.GetIntputOutputTrace(this.context.RawInput), + this.context.RawInput, exception, stopwatch.Elapsed.TotalMilliseconds, isReplay: false); From b1ec95d5b2d95bdbdc89de30bc54fe29300b5453 Mon Sep 17 00:00:00 2001 From: David Justo Date: Tue, 2 Jul 2024 17:03:12 -0700 Subject: [PATCH 24/30] remove replay controls --- .../EndToEndTraceHelper.cs | 59 +++++++++++-------- 1 file changed, 36 insertions(+), 23 deletions(-) diff --git a/src/WebJobs.Extensions.DurableTask/EndToEndTraceHelper.cs b/src/WebJobs.Extensions.DurableTask/EndToEndTraceHelper.cs index 3a502e430..f8c8b7587 100644 --- a/src/WebJobs.Extensions.DurableTask/EndToEndTraceHelper.cs +++ b/src/WebJobs.Extensions.DurableTask/EndToEndTraceHelper.cs @@ -59,39 +59,52 @@ public static string LocalSlotName #pragma warning disable SA1117 // Parameters should be on same line or separate lines - private void SanitizeString(string? rawPayload, out string iloggerString, out string durableKustoTableString, bool isReplay = false) + private void SanitizeString(string? rawPayload, out string iloggerString, out string durableKustoTableString) { - if (isReplay) - { - iloggerString = rawPayload ?? "(replay)"; - durableKustoTableString = "(replay)"; - } - string payload = rawPayload ?? "(null)"; - int numCharacters = payload.Length; + int numCharacters = rawPayload != null ? payload.Length : 0; string sanitizedPayload = $"(Redacted {numCharacters} characters)"; - iloggerString = this.shouldTraceRawData ? payload : sanitizedPayload; + // By default, both ilogger and kusto data should use the sanitized data + iloggerString = sanitizedPayload; durableKustoTableString = sanitizedPayload; + + // IFF users opts into tracing raw data, then their ILogger gets the raw data + if (this.shouldTraceRawData) + { + iloggerString = payload; + } } - private void SanitizeException(Exception? exception, out string iloggerExceptionString, out string durableKustoTableString, bool isReplay = false) + private void SanitizeException(Exception? exception, out string iloggerExceptionString, out string durableKustoTableString) { - string exceptionString = exception != null ? exception.ToString() : string.Empty; - if (exception is OrchestrationFailureException orchestrationFailureException) + // default case: exception is null + string rawError = string.Empty; + string sanitizedError = string.Empty; + + // if exception is not null + if (exception != null) { - exceptionString = orchestrationFailureException.Details; + // common case if exception is not null + rawError = exception.ToString(); + sanitizedError = $"{exception.GetType().FullName}\n{exception.StackTrace}"; + + // if exception is an OrchestrationFailureException, we need to unravel the details + if (exception is OrchestrationFailureException orchestrationFailureException) + { + rawError = orchestrationFailureException.Details; + } } - string sanitizedString = exception != null ? $"{exception.GetType().FullName}\n{exception.StackTrace}" : string.Empty; - iloggerExceptionString = this.shouldTraceRawData ? exceptionString : sanitizedString; + // By default, both ilogger and kusto data should use the sanitized string + iloggerExceptionString = sanitizedError; + durableKustoTableString = sanitizedError; - if (isReplay) + // IFF users opts into tracing raw data, then their ILogger gets the raw exception string + if (this.shouldTraceRawData) { - durableKustoTableString = "(replay)"; + iloggerExceptionString = rawError; } - - durableKustoTableString = sanitizedString; } public void ExtensionInformationalEvent( @@ -171,7 +184,7 @@ public void FunctionStarting( bool isReplay, int taskEventId = -1) { - this.SanitizeString(input, out string loggerInput, out string sanitizedInput, isReplay: isReplay); + this.SanitizeString(input, out string loggerInput, out string sanitizedInput); if (this.ShouldLogEvent(isReplay)) { @@ -259,7 +272,7 @@ public void FunctionCompleted( bool isReplay, int taskEventId = -1) { - this.SanitizeString(output, out string loggerOutput, out string sanitizedOutput, isReplay: isReplay); + this.SanitizeString(output, out string loggerOutput, out string sanitizedOutput); if (this.ShouldLogEvent(isReplay)) { @@ -400,7 +413,7 @@ public void FunctionFailed( bool isReplay, int taskEventId = -1) { - this.SanitizeException(exception, out string loggerReason, out string sanitizedReason, isReplay); + this.SanitizeException(exception, out string loggerReason, out string sanitizedReason); this.FunctionFailed(hubName, functionName, instanceId, loggerReason, sanitizedReason, functionType, isReplay, taskEventId); } @@ -509,7 +522,7 @@ public void OperationFailed( bool isReplay) { this.SanitizeString(input, out string loggerInput, out string sanitizedInput); - this.SanitizeException(exception, out string loggerException, out string sanitizedException, isReplay); + this.SanitizeException(exception, out string loggerException, out string sanitizedException); this.OperationFailed(hubName, functionName, instanceId, operationId, operationName, sanitizedInput, loggerInput, sanitizedException, loggerException, duration, isReplay); } From 73fed6e0d25c390ecb8192b64ae67911a18fa45b Mon Sep 17 00:00:00 2001 From: David Justo Date: Tue, 2 Jul 2024 17:35:19 -0700 Subject: [PATCH 25/30] add unit tests --- src/WebJobs.Extensions.DurableTask/EndToEndTraceHelper.cs | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/src/WebJobs.Extensions.DurableTask/EndToEndTraceHelper.cs b/src/WebJobs.Extensions.DurableTask/EndToEndTraceHelper.cs index f8c8b7587..dff451812 100644 --- a/src/WebJobs.Extensions.DurableTask/EndToEndTraceHelper.cs +++ b/src/WebJobs.Extensions.DurableTask/EndToEndTraceHelper.cs @@ -59,7 +59,7 @@ public static string LocalSlotName #pragma warning disable SA1117 // Parameters should be on same line or separate lines - private void SanitizeString(string? rawPayload, out string iloggerString, out string durableKustoTableString) + internal void SanitizeString(string? rawPayload, out string iloggerString, out string durableKustoTableString) { string payload = rawPayload ?? "(null)"; int numCharacters = rawPayload != null ? payload.Length : 0; @@ -76,7 +76,7 @@ private void SanitizeString(string? rawPayload, out string iloggerString, out st } } - private void SanitizeException(Exception? exception, out string iloggerExceptionString, out string durableKustoTableString) + internal void SanitizeException(Exception? exception, out string iloggerExceptionString, out string durableKustoTableString) { // default case: exception is null string rawError = string.Empty; From e16b9126e6e20bb2ec24e96b65ce7fc5fdaeb17d Mon Sep 17 00:00:00 2001 From: David Justo Date: Tue, 2 Jul 2024 17:36:25 -0700 Subject: [PATCH 26/30] Add unit tests --- test/FunctionsV2/EndToEndTraceHelperTests.cs | 100 +++++++++++++++++++ 1 file changed, 100 insertions(+) create mode 100644 test/FunctionsV2/EndToEndTraceHelperTests.cs diff --git a/test/FunctionsV2/EndToEndTraceHelperTests.cs b/test/FunctionsV2/EndToEndTraceHelperTests.cs new file mode 100644 index 000000000..9fa008c4d --- /dev/null +++ b/test/FunctionsV2/EndToEndTraceHelperTests.cs @@ -0,0 +1,100 @@ +// Copyright (c) .NET Foundation. All rights reserved. +// Licensed under the MIT License. See LICENSE in the project root for license information. + +#nullable enable +using System; +using Microsoft.Azure.WebJobs.Extensions.DurableTask; +using Microsoft.Extensions.Logging.Abstractions; +using Xunit; + +namespace WebJobs.Extensions.DurableTask.Tests.V2 +{ + public class EndToEndTraceHelperTests + { + [Theory] + [InlineData(true, true)] + [InlineData(false, true)] + [InlineData(true, false)] + [InlineData(false, false)] + public void StringSanitizerTest(bool shouldTraceRawData, bool testNullInput) + { + // set up trace helper + var nullLogger = new NullLogger(); + var traceHelper = new EndToEndTraceHelper( + logger: nullLogger, + traceReplayEvents: false, // has not effect on sanitizer + shouldTraceRawData: shouldTraceRawData); + + // prepare sensitive data to sanitize + string possibleSensitiveData = "DO NOT LOG ME"; + + // run sanitizer + traceHelper.SanitizeString( + rawPayload: testNullInput ? null : possibleSensitiveData, + out string iLoggerString, + out string kustoTableString); + + // expected: sanitized string should not contain the sensitive data + Assert.DoesNotContain(possibleSensitiveData, kustoTableString); + + if (shouldTraceRawData) + { + if (testNullInput) + { + // If provided input is null, it is logged as "(null)" + Assert.Equal("(null)", iLoggerString); + } + else + { + // Otherwise, we expect to see the data as-is + Assert.Equal(possibleSensitiveData, iLoggerString); + } + } + else + { + // If raw data is not being traced, + // kusto and the ilogger should get the same data + Assert.Equal(iLoggerString, kustoTableString); + } + } + + + [Theory] + [InlineData(true, true)] + [InlineData(false, true)] + [InlineData(true, false)] + [InlineData(false, false)] + public void ExceptionSanitizerTest(bool shouldTraceRawData, bool testNullInput) + { + // set up trace helper + var nullLogger = new NullLogger(); + var traceHelper = new EndToEndTraceHelper( + logger: nullLogger, + traceReplayEvents: false, // has not effect on sanitizer + shouldTraceRawData: shouldTraceRawData); + + // exception to sanitize + var possiblySensitiveData = "DO NOT LOG ME"; + var exception = new Exception(possiblySensitiveData); + + // run sanitizer + traceHelper.SanitizeException( + exception: testNullInput ? null : exception, + out string iLoggerString, + out string kustoTableString); + + // exception message should not be part of the sanitized strings + Assert.DoesNotContain(possiblySensitiveData, kustoTableString); + + if (shouldTraceRawData) + { + var expectedString = testNullInput ? string.Empty : exception.ToString(); + Assert.Equal(expectedString, iLoggerString); + } + else + { + Assert.Equal(iLoggerString, kustoTableString); + } + } + } +} From 8ed5d302e7c69b2592167afd5abd63922792dc9a Mon Sep 17 00:00:00 2001 From: David Justo Date: Tue, 2 Jul 2024 17:59:35 -0700 Subject: [PATCH 27/30] clean up tests --- .../EndToEndTraceHelper.cs | 4 +- test/FunctionsV2/EndToEndTraceHelperTests.cs | 66 ++++++++++--------- 2 files changed, 38 insertions(+), 32 deletions(-) diff --git a/src/WebJobs.Extensions.DurableTask/EndToEndTraceHelper.cs b/src/WebJobs.Extensions.DurableTask/EndToEndTraceHelper.cs index dff451812..8d7e2ddd6 100644 --- a/src/WebJobs.Extensions.DurableTask/EndToEndTraceHelper.cs +++ b/src/WebJobs.Extensions.DurableTask/EndToEndTraceHelper.cs @@ -61,8 +61,8 @@ public static string LocalSlotName internal void SanitizeString(string? rawPayload, out string iloggerString, out string durableKustoTableString) { - string payload = rawPayload ?? "(null)"; - int numCharacters = rawPayload != null ? payload.Length : 0; + string payload = rawPayload ?? string.Empty; + int numCharacters = payload.Length; string sanitizedPayload = $"(Redacted {numCharacters} characters)"; // By default, both ilogger and kusto data should use the sanitized data diff --git a/test/FunctionsV2/EndToEndTraceHelperTests.cs b/test/FunctionsV2/EndToEndTraceHelperTests.cs index 9fa008c4d..e02d8991c 100644 --- a/test/FunctionsV2/EndToEndTraceHelperTests.cs +++ b/test/FunctionsV2/EndToEndTraceHelperTests.cs @@ -12,11 +12,13 @@ namespace WebJobs.Extensions.DurableTask.Tests.V2 public class EndToEndTraceHelperTests { [Theory] - [InlineData(true, true)] - [InlineData(false, true)] - [InlineData(true, false)] - [InlineData(false, false)] - public void StringSanitizerTest(bool shouldTraceRawData, bool testNullInput) + [InlineData(true, "DO NOT LOG ME")] + [InlineData(false, "DO NOT LOG ME")] + [InlineData(true, null)] + [InlineData(false, null)] + public void StringSanitizerTest( + bool shouldTraceRawData, + string? possiblySensitiveData) { // set up trace helper var nullLogger = new NullLogger(); @@ -25,30 +27,23 @@ public void StringSanitizerTest(bool shouldTraceRawData, bool testNullInput) traceReplayEvents: false, // has not effect on sanitizer shouldTraceRawData: shouldTraceRawData); - // prepare sensitive data to sanitize - string possibleSensitiveData = "DO NOT LOG ME"; - // run sanitizer traceHelper.SanitizeString( - rawPayload: testNullInput ? null : possibleSensitiveData, + rawPayload: possiblySensitiveData, out string iLoggerString, out string kustoTableString); // expected: sanitized string should not contain the sensitive data - Assert.DoesNotContain(possibleSensitiveData, kustoTableString); + // skip this check if data is null + if (possiblySensitiveData != null) + { + Assert.DoesNotContain(possiblySensitiveData, kustoTableString); + } if (shouldTraceRawData) { - if (testNullInput) - { - // If provided input is null, it is logged as "(null)" - Assert.Equal("(null)", iLoggerString); - } - else - { - // Otherwise, we expect to see the data as-is - Assert.Equal(possibleSensitiveData, iLoggerString); - } + string expectedString = possiblySensitiveData ?? string.Empty; + Assert.Equal(expectedString, iLoggerString); } else { @@ -60,11 +55,13 @@ public void StringSanitizerTest(bool shouldTraceRawData, bool testNullInput) [Theory] - [InlineData(true, true)] - [InlineData(false, true)] - [InlineData(true, false)] - [InlineData(false, false)] - public void ExceptionSanitizerTest(bool shouldTraceRawData, bool testNullInput) + [InlineData(true, "DO NOT LOG ME")] + [InlineData(false, "DO NOT LOG ME")] + [InlineData(true, null)] + [InlineData(false, null)] + public void ExceptionSanitizerTest( + bool shouldTraceRawData, + string? possiblySensitiveData) { // set up trace helper var nullLogger = new NullLogger(); @@ -74,25 +71,34 @@ public void ExceptionSanitizerTest(bool shouldTraceRawData, bool testNullInput) shouldTraceRawData: shouldTraceRawData); // exception to sanitize - var possiblySensitiveData = "DO NOT LOG ME"; - var exception = new Exception(possiblySensitiveData); + Exception? exception = null; + if (possiblySensitiveData != null) + { + exception = new Exception(possiblySensitiveData); + } // run sanitizer traceHelper.SanitizeException( - exception: testNullInput ? null : exception, + exception: exception, out string iLoggerString, out string kustoTableString); // exception message should not be part of the sanitized strings - Assert.DoesNotContain(possiblySensitiveData, kustoTableString); + // skip this check if data is null + if (possiblySensitiveData != null) + { + Assert.DoesNotContain(possiblySensitiveData, kustoTableString); + } if (shouldTraceRawData) { - var expectedString = testNullInput ? string.Empty : exception.ToString(); + var expectedString = exception?.ToString() ?? string.Empty; Assert.Equal(expectedString, iLoggerString); } else { + // If raw data is not being traced, + // kusto and the ilogger should get the same data Assert.Equal(iLoggerString, kustoTableString); } } From 5d15568fcc784ae46cc480c512ea6ebe00299ccc Mon Sep 17 00:00:00 2001 From: David Justo Date: Mon, 8 Jul 2024 12:32:25 -0700 Subject: [PATCH 28/30] pass tests --- test/Common/TestHelpers.cs | 4 ++-- test/FunctionsV2/EndToEndTraceHelperTests.cs | 3 +++ 2 files changed, 5 insertions(+), 2 deletions(-) diff --git a/test/Common/TestHelpers.cs b/test/Common/TestHelpers.cs index e89c09978..a6c455e3a 100644 --- a/test/Common/TestHelpers.cs +++ b/test/Common/TestHelpers.cs @@ -703,7 +703,7 @@ private static List GetLogs_UnhandledOrchestrationException(string messa var list = new List() { $"{messageId}: Function '{orchestratorFunctionNames[0]} ({FunctionType.Orchestrator})' scheduled. Reason: NewInstance. IsReplay: False.", - $"{messageId}: Function '{orchestratorFunctionNames[0]} ({FunctionType.Orchestrator})' started. IsReplay: False. Input: (null)", + $"{messageId}: Function '{orchestratorFunctionNames[0]} ({FunctionType.Orchestrator})' started. IsReplay: False. Input: ", $"{messageId}: Function '{orchestratorFunctionNames[0]} ({FunctionType.Orchestrator})' failed with an error. Reason: System.ArgumentNullException: Value cannot be null.", }; @@ -831,7 +831,7 @@ private static List GetLogs_Orchestration_Activity(string[] messageIds, $"{messageIds[1]}:0: Function '{orchestratorFunctionNames[1]} ({FunctionType.Orchestrator})' completed. ContinuedAsNew: False. IsReplay: False. Output: \"Hello,", $"{messageIds[0]}: Function '{orchestratorFunctionNames[0]} ({FunctionType.Orchestrator})' started. IsReplay: True.", $"{messageIds[0]}: Function '{orchestratorFunctionNames[1]} ({FunctionType.Orchestrator})' scheduled. Reason: OrchestratorGreeting. IsReplay: True.", - $"{messageIds[0]}: Function '{orchestratorFunctionNames[0]} ({FunctionType.Orchestrator})' completed. ContinuedAsNew: False. IsReplay: False. Output: (null)", + $"{messageIds[0]}: Function '{orchestratorFunctionNames[0]} ({FunctionType.Orchestrator})' completed. ContinuedAsNew: False. IsReplay: False. Output: ", }; return list; diff --git a/test/FunctionsV2/EndToEndTraceHelperTests.cs b/test/FunctionsV2/EndToEndTraceHelperTests.cs index e02d8991c..1440a367a 100644 --- a/test/FunctionsV2/EndToEndTraceHelperTests.cs +++ b/test/FunctionsV2/EndToEndTraceHelperTests.cs @@ -4,6 +4,7 @@ #nullable enable using System; using Microsoft.Azure.WebJobs.Extensions.DurableTask; +using Microsoft.Azure.WebJobs.Extensions.DurableTask.Tests; using Microsoft.Extensions.Logging.Abstractions; using Xunit; @@ -16,6 +17,7 @@ public class EndToEndTraceHelperTests [InlineData(false, "DO NOT LOG ME")] [InlineData(true, null)] [InlineData(false, null)] + [Trait("Category", PlatformSpecificHelpers.TestCategory)] public void StringSanitizerTest( bool shouldTraceRawData, string? possiblySensitiveData) @@ -59,6 +61,7 @@ public void StringSanitizerTest( [InlineData(false, "DO NOT LOG ME")] [InlineData(true, null)] [InlineData(false, null)] + [Trait("Category", PlatformSpecificHelpers.TestCategory)] public void ExceptionSanitizerTest( bool shouldTraceRawData, string? possiblySensitiveData) From 778cecda8274f374cc10e5109b15fe8dc07873c6 Mon Sep 17 00:00:00 2001 From: David Justo Date: Mon, 8 Jul 2024 13:05:05 -0700 Subject: [PATCH 29/30] increase timeout --- test/Common/TestDurableClient.cs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/test/Common/TestDurableClient.cs b/test/Common/TestDurableClient.cs index 6e35e5e49..9e70d092b 100644 --- a/test/Common/TestDurableClient.cs +++ b/test/Common/TestDurableClient.cs @@ -182,7 +182,7 @@ public async Task WaitForCompletionAsync( { if (timeout == null) { - timeout = Debugger.IsAttached ? TimeSpan.FromMinutes(5) : TimeSpan.FromMinutes(1); + timeout = Debugger.IsAttached ? TimeSpan.FromMinutes(5) : TimeSpan.FromMinutes(3); // 3 minutes because AzureStorage emulator can be slow } Stopwatch sw = Stopwatch.StartNew(); From bac3b3376cc75c1b4d8a8f4fd10a5b4b84257b85 Mon Sep 17 00:00:00 2001 From: David Justo Date: Tue, 9 Jul 2024 09:03:38 -0700 Subject: [PATCH 30/30] pass linter --- test/Common/TestDurableClient.cs | 2 +- test/FunctionsV2/EndToEndTraceHelperTests.cs | 1 - 2 files changed, 1 insertion(+), 2 deletions(-) diff --git a/test/Common/TestDurableClient.cs b/test/Common/TestDurableClient.cs index 9e70d092b..6e35e5e49 100644 --- a/test/Common/TestDurableClient.cs +++ b/test/Common/TestDurableClient.cs @@ -182,7 +182,7 @@ public async Task WaitForCompletionAsync( { if (timeout == null) { - timeout = Debugger.IsAttached ? TimeSpan.FromMinutes(5) : TimeSpan.FromMinutes(3); // 3 minutes because AzureStorage emulator can be slow + timeout = Debugger.IsAttached ? TimeSpan.FromMinutes(5) : TimeSpan.FromMinutes(1); } Stopwatch sw = Stopwatch.StartNew(); diff --git a/test/FunctionsV2/EndToEndTraceHelperTests.cs b/test/FunctionsV2/EndToEndTraceHelperTests.cs index 1440a367a..4ea1b4e06 100644 --- a/test/FunctionsV2/EndToEndTraceHelperTests.cs +++ b/test/FunctionsV2/EndToEndTraceHelperTests.cs @@ -55,7 +55,6 @@ public void StringSanitizerTest( } } - [Theory] [InlineData(true, "DO NOT LOG ME")] [InlineData(false, "DO NOT LOG ME")]