diff --git a/Test/DurableTask.Core.Tests/TaskOrchestrationContextTests.cs b/Test/DurableTask.Core.Tests/TaskOrchestrationContextTests.cs index a19d76a20..8267475c6 100644 --- a/Test/DurableTask.Core.Tests/TaskOrchestrationContextTests.cs +++ b/Test/DurableTask.Core.Tests/TaskOrchestrationContextTests.cs @@ -147,6 +147,29 @@ public async Task ScheduleTask_WithFailure_ShouldPropagateException() } } + [TestMethod] + public void GetOpenTasksSummary_WithNoOpenTasks_ReturnsEmptyString() + { + string summary = context.GetOpenTasksSummary(); + Assert.AreEqual(string.Empty, summary); + } + + [TestMethod] + public void GetOpenTasksSummary_WithManyOpenTasks_UsesBoundedSummary() + { + for (int i = 0; i < 100; i++) + { + _ = context.ScheduleTask(new string('A', 100), "1.0", i); + } + + Assert.AreEqual(100, context.OpenTaskCount); + + string summary = context.GetOpenTasksSummary(); + + Assert.IsTrue(summary.Length <= 1024, "Summary should be capped to the configured maximum length."); + Assert.IsTrue(summary.Contains("more task(s))"), "Summary should indicate omitted tasks when capped."); + } + private class MockTaskOrchestrationContext : TaskOrchestrationContext { public List ScheduledTasks { get; } = new List(); diff --git a/src/DurableTask.Core/Logging/LogEvents.cs b/src/DurableTask.Core/Logging/LogEvents.cs index e5fe2ee33..5ee6615f5 100644 --- a/src/DurableTask.Core/Logging/LogEvents.cs +++ b/src/DurableTask.Core/Logging/LogEvents.cs @@ -929,12 +929,19 @@ void IEventSourceEvent.WriteEventSource() => /// internal class OrchestrationExecuted : StructuredLogEvent, IEventSourceEvent { - public OrchestrationExecuted(OrchestrationInstance instance, string name, int actionCount) + public OrchestrationExecuted( + OrchestrationInstance instance, + string name, + int actionCount, + int openTaskCount, + string openTaskNames) { this.InstanceId = instance.InstanceId; this.ExecutionId = instance.ExecutionId ?? string.Empty; this.Name = name; this.ActionCount = actionCount; + this.OpenTaskCount = openTaskCount; + this.OpenTaskNames = openTaskNames ?? string.Empty; } [StructuredLogField] @@ -949,14 +956,28 @@ public OrchestrationExecuted(OrchestrationInstance instance, string name, int ac [StructuredLogField] public int ActionCount { get; } + [StructuredLogField] + public int OpenTaskCount { get; } + + [StructuredLogField] + public string OpenTaskNames { get; } + public override EventId EventId => new EventId( EventIds.OrchestrationExecuted, nameof(EventIds.OrchestrationExecuted)); public override LogLevel Level => LogLevel.Information; - protected override string CreateLogMessage() => - $"{this.InstanceId}: Orchestration '{this.Name}' awaited and scheduled {this.ActionCount} durable operation(s)."; + protected override string CreateLogMessage() + { + string message = $"{this.InstanceId}: Orchestration '{this.Name}' awaited and scheduled {this.ActionCount} durable operation(s)."; + if (this.OpenTaskCount > 0) + { + message += $" {this.OpenTaskCount} pending task(s): {this.OpenTaskNames}"; + } + + return message; + } void IEventSourceEvent.WriteEventSource() => StructuredEventSource.Log.OrchestrationExecuted( @@ -964,6 +985,8 @@ void IEventSourceEvent.WriteEventSource() => this.ExecutionId, this.Name, this.ActionCount, + this.OpenTaskCount, + this.OpenTaskNames, Utils.AppName, Utils.PackageVersion); } diff --git a/src/DurableTask.Core/Logging/LogHelper.cs b/src/DurableTask.Core/Logging/LogHelper.cs index 6efbe0cfe..35d3bf1dc 100644 --- a/src/DurableTask.Core/Logging/LogHelper.cs +++ b/src/DurableTask.Core/Logging/LogHelper.cs @@ -432,14 +432,19 @@ internal void OrchestrationExecuting(OrchestrationInstance instance, string name /// The orchestration instance that was executed. /// The name of the orchestration. /// The actions taken by the orchestration + /// The number of pending tasks awaiting completion. + /// A summary of the pending task names. internal void OrchestrationExecuted( OrchestrationInstance instance, string name, - IReadOnlyList actions) + IReadOnlyList actions, + int openTaskCount, + string openTaskNames) { if (this.IsStructuredLoggingEnabled) { - this.WriteStructuredLog(new LogEvents.OrchestrationExecuted(instance, name, actions.Count)); + this.WriteStructuredLog(new LogEvents.OrchestrationExecuted( + instance, name, actions.Count, openTaskCount, openTaskNames)); } } diff --git a/src/DurableTask.Core/Logging/StructuredEventSource.cs b/src/DurableTask.Core/Logging/StructuredEventSource.cs index 129bac158..309506973 100644 --- a/src/DurableTask.Core/Logging/StructuredEventSource.cs +++ b/src/DurableTask.Core/Logging/StructuredEventSource.cs @@ -496,6 +496,8 @@ internal void OrchestrationExecuted( string ExecutionId, string Name, int ActionCount, + int OpenTaskCount, + string OpenTaskNames, string AppName, string ExtensionVersion) { @@ -508,6 +510,8 @@ internal void OrchestrationExecuted( ExecutionId, Name, ActionCount, + OpenTaskCount, + OpenTaskNames, AppName, ExtensionVersion); } diff --git a/src/DurableTask.Core/OrchestrationExecutionCursor.cs b/src/DurableTask.Core/OrchestrationExecutionCursor.cs index 90ad420f8..67d3c4e92 100644 --- a/src/DurableTask.Core/OrchestrationExecutionCursor.cs +++ b/src/DurableTask.Core/OrchestrationExecutionCursor.cs @@ -37,5 +37,9 @@ public OrchestrationExecutionCursor( public TaskOrchestrationExecutor OrchestrationExecutor { get; } public IEnumerable LatestDecisions { get; set; } + + public int OpenTaskCount { get; set; } + + public string OpenTaskNames { get; set; } = string.Empty; } } diff --git a/src/DurableTask.Core/OrchestratorExecutionResult.cs b/src/DurableTask.Core/OrchestratorExecutionResult.cs index 849692e3d..a6b98bcbf 100644 --- a/src/DurableTask.Core/OrchestratorExecutionResult.cs +++ b/src/DurableTask.Core/OrchestratorExecutionResult.cs @@ -36,6 +36,20 @@ public class OrchestratorExecutionResult [JsonProperty("customStatus")] public string? CustomStatus { get; set; } + /// + /// The number of tasks that the orchestration is currently waiting on. + /// This is used for diagnostic purposes and is not serialized. + /// + [JsonIgnore] + internal int OpenTaskCount { get; set; } + + /// + /// A summary of the open tasks the orchestration is waiting on (e.g., "GetData#3, Timer#5"). + /// This is used for diagnostic purposes and is not serialized. + /// + [JsonIgnore] + internal string OpenTaskNames { get; set; } = string.Empty; + /// /// Creates an orchestrator failure result with a specified message and exception. /// diff --git a/src/DurableTask.Core/TaskOrchestrationContext.cs b/src/DurableTask.Core/TaskOrchestrationContext.cs index e4846124c..f1f9dad6a 100644 --- a/src/DurableTask.Core/TaskOrchestrationContext.cs +++ b/src/DurableTask.Core/TaskOrchestrationContext.cs @@ -18,6 +18,7 @@ namespace DurableTask.Core using System.Diagnostics; using System.Globalization; using System.Linq; + using System.Text; using System.Threading; using System.Threading.Tasks; using DurableTask.Core.Command; @@ -30,6 +31,8 @@ namespace DurableTask.Core internal class TaskOrchestrationContext : OrchestrationContext { + private const int MaxOpenTaskSummaryEntries = 32; + private const int MaxOpenTaskSummaryLength = 1024; private readonly IDictionary openTasks; private readonly IDictionary orchestratorActionsMap; private OrchestrationCompleteOrchestratorAction continueAsNew; @@ -75,6 +78,75 @@ public TaskOrchestrationContext( public bool HasOpenTasks => this.openTasks.Count > 0; + internal int OpenTaskCount => this.openTasks.Count; + + internal string GetOpenTasksSummary() + { + int openTaskCount = this.openTasks.Count; + if (openTaskCount == 0) + { + return string.Empty; + } + + var summaryBuilder = new StringBuilder(Math.Min(openTaskCount * 16, MaxOpenTaskSummaryLength)); + int includedEntries = 0; + bool summaryTruncatedByLength = false; + + foreach (KeyValuePair openTask in this.openTasks) + { + if (includedEntries >= MaxOpenTaskSummaryEntries) + { + break; + } + + string entry = $"{openTask.Value.Name ?? "Timer"}#{openTask.Key}"; + int separatorLength = includedEntries > 0 ? 2 : 0; + int requiredLength = separatorLength + entry.Length; + + if (summaryBuilder.Length + requiredLength > MaxOpenTaskSummaryLength) + { + summaryTruncatedByLength = true; + break; + } + + if (separatorLength > 0) + { + summaryBuilder.Append(", "); + } + + summaryBuilder.Append(entry); + includedEntries++; + } + + int omittedTaskCount = openTaskCount - includedEntries; + if (omittedTaskCount > 0 || summaryTruncatedByLength) + { + string suffix = $"... (+{omittedTaskCount} more task(s))"; + int separatorLength = summaryBuilder.Length > 0 ? 2 : 0; + int requiredLength = separatorLength + suffix.Length; + + if (summaryBuilder.Length + requiredLength > MaxOpenTaskSummaryLength) + { + int maxPrefixLength = MaxOpenTaskSummaryLength - requiredLength; + if (maxPrefixLength < 0) + { + return suffix.Substring(0, MaxOpenTaskSummaryLength); + } + + summaryBuilder.Length = Math.Min(summaryBuilder.Length, maxPrefixLength); + } + + if (separatorLength > 0) + { + summaryBuilder.Append(", "); + } + + summaryBuilder.Append(suffix); + } + + return summaryBuilder.ToString(); + } + internal void ClearPendingActions() { this.orchestratorActionsMap.Clear(); diff --git a/src/DurableTask.Core/TaskOrchestrationDispatcher.cs b/src/DurableTask.Core/TaskOrchestrationDispatcher.cs index 751a64b78..17e1e5fe3 100644 --- a/src/DurableTask.Core/TaskOrchestrationDispatcher.cs +++ b/src/DurableTask.Core/TaskOrchestrationDispatcher.cs @@ -464,10 +464,15 @@ protected async Task OnProcessWorkItemAsync(TaskOrchestrationWorkItem work } } + int openTaskCount = workItem.Cursor?.OpenTaskCount ?? 0; + string openTaskNames = workItem.Cursor?.OpenTaskNames ?? string.Empty; + this.logHelper.OrchestrationExecuted( runtimeState.OrchestrationInstance!, runtimeState.Name, - decisions); + decisions, + openTaskCount, + openTaskNames); TraceHelper.TraceInstance( TraceEventType.Information, "TaskOrchestrationDispatcher-ExecuteUserOrchestration-End", @@ -825,10 +830,13 @@ await this.dispatchPipeline.RunAsync(dispatchContext, _ => }); var result = dispatchContext.GetProperty(); - IEnumerable decisions = result?.Actions ?? Enumerable.Empty(); + var decisions = (result?.Actions ?? Enumerable.Empty()).ToList(); runtimeState.Status = result?.CustomStatus; - return new OrchestrationExecutionCursor(runtimeState, taskOrchestration, executor, decisions); + var cursor = new OrchestrationExecutionCursor(runtimeState, taskOrchestration, executor, decisions); + cursor.OpenTaskCount = result?.OpenTaskCount ?? 0; + cursor.OpenTaskNames = result?.OpenTaskNames ?? string.Empty; + return cursor; } async Task ResumeOrchestrationAsync(TaskOrchestrationWorkItem workItem) @@ -860,8 +868,12 @@ await this.dispatchPipeline.RunAsync(dispatchContext, _ => }); var result = dispatchContext.GetProperty(); - cursor.LatestDecisions = result?.Actions ?? Enumerable.Empty(); + var decisions = (result?.Actions ?? Enumerable.Empty()).ToList(); cursor.RuntimeState.Status = result?.CustomStatus; + + cursor.LatestDecisions = decisions; + cursor.OpenTaskCount = result?.OpenTaskCount ?? 0; + cursor.OpenTaskNames = result?.OpenTaskNames ?? string.Empty; } /// diff --git a/src/DurableTask.Core/TaskOrchestrationExecutor.cs b/src/DurableTask.Core/TaskOrchestrationExecutor.cs index 540851e50..740aa4ea4 100644 --- a/src/DurableTask.Core/TaskOrchestrationExecutor.cs +++ b/src/DurableTask.Core/TaskOrchestrationExecutor.cs @@ -212,6 +212,8 @@ void ProcessEvents(IEnumerable events) { Actions = this.context.OrchestratorActions, CustomStatus = this.taskOrchestration.GetStatus(), + OpenTaskCount = this.context.OpenTaskCount, + OpenTaskNames = this.context.GetOpenTasksSummary(), }; } finally