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

src/DurableTask.Core/Logging/EventIds.cs

@@ -63,5 +63,7 @@ static class EventIds
         public const int RenewOrchestrationWorkItemStarting = 70;
         public const int RenewOrchestrationWorkItemCompleted = 71;
         public const int RenewOrchestrationWorkItemFailed = 72;
+
+        public const int OrchestrationDebugTrace = 73;
     }
 }

src/DurableTask.Core/Logging/LogEvents.cs

@@ -1629,5 +1629,45 @@ void IEventSourceEvent.WriteEventSource() =>
                     Utils.AppName,
                     Utils.PackageVersion);
         }
+
+        internal class OrchestrationDebugTrace : StructuredLogEvent, IEventSourceEvent
+        {
+            public OrchestrationDebugTrace(string instanceId, string executionId, string details)
+            {
+                this.InstanceId = instanceId;
+                this.ExecutionId = executionId;
+                this.Details = details;
+            }
+
+            [StructuredLogField]
+            public string InstanceId { get; }
+
+            [StructuredLogField]
+            public string ExecutionId { get; }
+
+            [StructuredLogField]
+            public string Name { get; }
+
+            [StructuredLogField]
+            public string Details { get; }
+
+            public override EventId EventId => new EventId(
+                EventIds.OrchestrationDebugTrace,
+                nameof(EventIds.OrchestrationDebugTrace));
+
+            public override LogLevel Level => LogLevel.Debug;
+
+            protected override string CreateLogMessage() =>
+                $"{this.InstanceId}: Orchestration Debug Trace: {this.Details}";
+
+            void IEventSourceEvent.WriteEventSource() =>
+                StructuredEventSource.Log.OrchestrationDebugTrace(
+                    this.InstanceId,
+                    this.ExecutionId,
+                    this.Details,
+                    Utils.AppName,
+                    Utils.PackageVersion);
+        }
+
     }
 }

src/DurableTask.Core/Logging/LogHelper.cs

@@ -678,6 +678,14 @@ internal void RenewActivityMessageFailed(TaskActivityWorkItem workItem, Exceptio
         }
         #endregion
 
+        internal void OrchestrationDebugTrace(string instanceId, string executionId, string details)
+        {
+            if (this.IsStructuredLoggingEnabled)
+            {
+                this.WriteStructuredLog(new LogEvents.OrchestrationDebugTrace(instanceId, executionId, details));
+            }
+        }
+
         void WriteStructuredLog(ILogEvent logEvent, Exception? exception = null)
         {
             this.log?.LogDurableEvent(logEvent, exception);

src/DurableTask.Core/Logging/StructuredEventSource.cs

@@ -865,5 +865,25 @@ internal void RenewOrchestrationWorkItemFailed(
                     ExtensionVersion);
             }
         }
+
+        [Event(EventIds.OrchestrationDebugTrace, Level = EventLevel.Verbose, Version = 1)]
+        internal void OrchestrationDebugTrace(
+            string InstanceId,
+            string ExecutionId,
+            string Details,
+            string AppName,
+            string ExtensionVersion)
+        {
+            if (this.IsEnabled(EventLevel.Verbose))
+            {
+                this.WriteEvent(
+                    EventIds.OrchestrationDebugTrace,
+                    InstanceId,
+                    ExecutionId,
+                    Details,
+                    AppName,
+                    ExtensionVersion);
+            }
+        }
     }
 }

src/DurableTask.Core/OrchestrationRuntimeState.cs

@@ -18,6 +18,7 @@ namespace DurableTask.Core
     using System.Diagnostics;
     using DurableTask.Core.Common;
     using DurableTask.Core.History;
+    using DurableTask.Core.Logging;
     using DurableTask.Core.Tracing;
 
     /// <summary>
@@ -184,6 +185,14 @@ public OrchestrationStatus OrchestrationStatus
             this.Events.Count == 1 && this.Events[0].EventType == EventType.OrchestratorStarted ||
             this.ExecutionStartedEvent != null;
 
+        /// <summary>
+        /// Gets or sets a LogHelper instance that can be used to log messages.
+        /// </summary>
+        /// <remarks>
+        /// Ideally, this would be set in the constructor but that would require a larger refactoring.
+        /// </remarks>
+        internal LogHelper? LogHelper { get; set; } = null;
+
         /// <summary>
         /// Adds a new history event to the Events list and NewEvents list
         /// </summary>
@@ -260,14 +269,33 @@ void SetMarkerEvents(HistoryEvent historyEvent)
             }
             else if (historyEvent is ExecutionCompletedEvent completedEvent)
             {
-                if (ExecutionCompletedEvent != null)
+                if (ExecutionCompletedEvent == null)
                 {
-                    throw new InvalidOperationException(
-                        "Multiple ExecutionCompletedEvent found, potential corruption in state storage");
+                    ExecutionCompletedEvent = completedEvent;
+                    orchestrationStatus = completedEvent.OrchestrationStatus;
+                }
+                else
+                {
+                    // 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 = $"Received new {completedEvent.GetType().Name} event despite the orchestration being already in the {orchestrationStatus} state.";
+
+                    if (orchestrationStatus == OrchestrationStatus.ContinuedAsNew && completedEvent.OrchestrationStatus == OrchestrationStatus.Terminated)
+                    {
+                        // If the orchestration planned to continue-as-new but termination is requested, we transition to the terminated state.
+                        // This is because termination should be considered to be forceful.
+                        log += " Discarding previous 'ExecutionCompletedEvent' as termination is forceful.";
+                        ExecutionCompletedEvent = completedEvent;
+                        orchestrationStatus = completedEvent.OrchestrationStatus;
+                    }
+                    else
+                    {
+                        // otherwise, we ignore the new event.
+                        log += " Discarding new 'ExecutionCompletedEvent'.";
+                    }
+
+                    LogHelper?.OrchestrationDebugTrace(this.OrchestrationInstance?.InstanceId ?? "", this.OrchestrationInstance?.ExecutionId ?? "", log);
                 }
-
-                ExecutionCompletedEvent = completedEvent;
-                orchestrationStatus = completedEvent.OrchestrationStatus;
             }
             else if (historyEvent is ExecutionSuspendedEvent)
             {

src/DurableTask.Core/TaskOrchestrationDispatcher.cs

@@ -296,6 +296,7 @@ protected async Task<bool> OnProcessWorkItemAsync(TaskOrchestrationWorkItem work
             IList<HistoryEvent>? carryOverEvents = null;
             string? carryOverStatus = null;
 
+            workItem.OrchestrationRuntimeState.LogHelper = this.logHelper;
             OrchestrationRuntimeState runtimeState = workItem.OrchestrationRuntimeState;
 
             runtimeState.AddEvent(new OrchestratorStartedEvent(-1));