Log warning on multiple execution completed events and allow termination to override previous execution completed events #949

davidmrdavid · 2023-09-05T22:39:27Z

Replaces: https://github.com/Azure/durabletask/pull/901/files
From this feedback: https://github.com/Azure/durabletask/pull/901/files#r1316325503

Currently, we throw an exception if we receive multiple ExecutionCompletedEvents. That behavior is a bit too strict because it is possible for multiple ExecutionCompletedEvents to be received at once. For example: when a termination signal arrives at the same time as an orchestrator is requested to continue-as-new.

This PR introduces two changes to this behavior:
(1) Instead of throwing an exception like we do today, we now log a warning notifying the reader that we've found multiple execution completed events and how DTFx is resolving this conflict.

(2) If orchestrator is ~~not in the terminated state and the a new event aims to terminate it, the new event overrides the previously encountered ExecutionCompletedEvent~~ planning to continue-as-new but a termination request is received, we transition to the "Terminated" state; this is because termination should be forceful. In all other cases, we discard the new execution completed event.

…g error

cgillum · 2023-09-05T22:43:15Z

src/DurableTask.Core/OrchestrationRuntimeState.cs

+                        log += "Discarding new 'ExecutionCompletedEvent'.";
+                    }
+
+                    TraceHelper.Trace(TraceEventType.Warning, "OrchestrationRuntimeState-DuplicateEvent", log);


This uses the old unstructured logging mechanism, which most users will never see. I think we need to instead find a way to use the LogHelper class here, perhaps by adding overloads to the methods that call into here which accept a LogHelper object.

Also, we'll want to be sure to use a log event that include an InstanceId field so that people filtering for events based on the instance ID can find it.

Hmm, I see what you mean.
My only concern with this request is that the refactoring to bring LogHelper here isn't trivial from what I can tell (e.g I can't just add a LogHelper parameter to OrchestrationRuntimeState.AddEvent() because AddEvent is public whereas LogHelper is internal), and so I worry about growing the scope of this PR.

Would you be willing to track modernizing the logging in this codepath that as a separate work item, or is this a blocker for you? If it's a blocker, I'll go ahead and starting working on it, but first I'm trying to determine my options.

A simple, if slightly hackly, solution would be to add an internal method or constructor overload that sets a private LogHelper field. if that field is non-null, then we can write the log message. It's probably not worth blocking on this, but at a minimum we should use a TraceHelper method that accepts an orchestration instance ID parameter. Otherwise, the logging is going to be pretty unhelpful.

I took your suggestion to create an internal method that sets a LogHelper field.

src/DurableTask.Core/OrchestrationRuntimeState.cs

cgillum · 2023-09-05T22:51:26Z

src/DurableTask.Core/OrchestrationRuntimeState.cs

-                        "Multiple ExecutionCompletedEvent found, potential corruption in state storage");
+                    // It's not generally expected to receive multiple execution completed events for a given orchestrator, but it's possible under certain race conditions.
+                    // For example: when an orchestrator is signaled to terminate at the same time as it attempts to continue-as-new.
+                    var log = $"The orchestration '{this.OrchestrationInstance?.InstanceId ?? ""}' " +


This log message feels a little too verbose. Can we simplify it to something like $"Ignoring {completedEvent.GetType().Name} event since the orchestration is already in the {orchestrationStatus} state.".

Sure, incorporated this in my next commit.

davidmrdavid · 2023-09-19T00:03:10Z

src/DurableTask.Core/Logging/EventIds.cs

+
+        public const int OrchestrationDebugTrace = 73;


It seemed to me that we were missing a general "debug trace" for logs like this one, so I decided to create one. It did not seem appropriate to create a very specific new category just for this log, so instead I created a more general one. I think this is a good idea considering that, as we recently learned with the entity logs, adding new EventIDs is expensive / can take a long time to deploy in Antares, so I wanted to make sure we have access to more general logging methods.

davidmrdavid · 2023-09-19T00:05:12Z

src/DurableTask.Core/OrchestrationRuntimeState.cs

+                        log += "Discarding new 'ExecutionCompletedEvent'.";
+                    }
+
+                    LogHelper?.OrchestrationDebugTrace(this.OrchestrationInstance?.InstanceId ?? "", this.OrchestrationInstance?.ExecutionId ?? "", log);


I did not find a pre-existing loghelper method that fit this case.

cgillum

cgillum · 2023-09-21T22:04:46Z

src/DurableTask.Core/OrchestrationRuntimeState.cs

                    // It's not generally expected to receive multiple execution completed events for a given orchestrator, but it's possible under certain race conditions.
                    // For example: when an orchestrator is signaled to terminate at the same time as it attempts to continue-as-new.
-                    var log = $"Ignoring {completedEvent.GetType().Name} event since the orchestration is already in the {orchestrationStatus} state.";
+                    var log = $"Received new {completedEvent.GetType().Name} event despite the orchestration being already in the {orchestrationStatus} state.";


I'm not a fan of this log change. You're saying we received an event but you're not saying what we're doing with it. The previous log made it clear that we're ignoring the new event.

@cgillum: I think there might be some confusion here. The log grows to include whether we decided to ignore the event later on. We don't always ignore the new event, as seen in the snippet below:

durabletask/src/DurableTask.Core/OrchestrationRuntimeState.cs

Lines 287 to 295 in 5a068aa

log += "Discarding previous 'ExecutionCompletedEvent' as termination is forceful.";

ExecutionCompletedEvent = completedEvent;

orchestrationStatus = completedEvent.OrchestrationStatus;

}

else

{

// otherwise, we ignore the new event.

log += "Discarding new 'ExecutionCompletedEvent'.";

}

So it's a log message that's created in two parts. First we capture that we're in a situation where we have to make a decision of which ExecutionCompletedEvent to preserve, and we include which one we decide to preserve (the new one or the previous one).

I see. In that case it's fine, but I think you need to add a space between the period in the first half of the log and the start of the next sentence.

addressed in latest commit: c23d3cc

superLionn · 2024-01-15T08:10:18Z

Hi team, may I ask the official release time?

davidmrdavid added 5 commits September 5, 2023 15:14

do not throw on multiple completed events, log a warning instead

2c3fa68

log warning on multiple execution completed events instead of throwin…

4deb515

…g error

typo

3b27f08

formatting fixes

f45b4cf

refactoring

4241a01

davidmrdavid requested a review from cgillum September 5, 2023 22:44

cgillum requested changes Sep 5, 2023

View reviewed changes

force termination only if orchestrator was planning to continue-as-new

d146047

davidmrdavid mentioned this pull request Sep 6, 2023

Multiple ExecutionCompletedEvent found microsoft/durabletask-mssql#176

Closed

address PR feedback

6f865c4

davidmrdavid commented Sep 19, 2023

View reviewed changes

davidmrdavid requested a review from cgillum September 19, 2023 00:06

cgillum approved these changes Sep 19, 2023

View reviewed changes

tweak compensation logic

5a068aa

cgillum reviewed Sep 21, 2023

View reviewed changes

adding spaces

c23d3cc

davidmrdavid merged commit 009f2e5 into main Dec 6, 2023

	log += "Discarding previous 'ExecutionCompletedEvent' as termination is forceful.";
	ExecutionCompletedEvent = completedEvent;
	orchestrationStatus = completedEvent.OrchestrationStatus;
	}
	else
	{
	// otherwise, we ignore the new event.
	log += "Discarding new 'ExecutionCompletedEvent'.";
	}

Log warning on multiple execution completed events and allow termination to override previous execution completed events #949

Log warning on multiple execution completed events and allow termination to override previous execution completed events #949

Uh oh!

Conversation

davidmrdavid commented Sep 5, 2023 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

Choose a reason for hiding this comment

Uh oh!

davidmrdavid Sep 5, 2023 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

davidmrdavid Sep 19, 2023 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

cgillum left a comment

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

superLionn commented Jan 15, 2024

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

3 participants

davidmrdavid commented Sep 5, 2023 •

edited

Loading

davidmrdavid Sep 5, 2023 •

edited

Loading

davidmrdavid Sep 19, 2023 •

edited

Loading