bugfix: ScheduledStartTime + start orch. actions

src/WebJobs.Extensions.DurableTask/ProtobufUtils.cs

@@ -573,6 +573,7 @@ internal static P.PurgeInstancesResponse CreatePurgeInstancesResponse(PurgeResul
                         InstanceId = operationAction.StartNewOrchestration.InstanceId,
                         Version = operationAction.StartNewOrchestration.Version,
                         RequestTime = operationAction.StartNewOrchestration.RequestTime?.ToDateTimeOffset(),
+                        ScheduledStartTime = operationAction.StartNewOrchestration.ScheduledTime?.ToDateTime(),
                         ParentTraceContext = operationAction.StartNewOrchestration.ParentTraceContext != null ?
                             new DistributedTraceContext(
                                 operationAction.StartNewOrchestration.ParentTraceContext.TraceParent,

test/e2e/Apps/BasicDotNetIsolated/EntityCreatesScheduledOrchestration.cs

@@ -0,0 +1,72 @@
+// Copyright (c) .NET Foundation. All rights reserved.
+// Licensed under the MIT License. See License.txt in the project root for license information.
+
+using Microsoft.Azure.Functions.Worker;
+using Microsoft.DurableTask;
+using Microsoft.DurableTask.Entities;
+
+using Microsoft.Azure.Functions.Worker.Http;
+using Microsoft.DurableTask.Client;
+using Microsoft.Extensions.Logging;
+
+namespace Microsoft.Azure.Durable.Tests.E2E;
+
+public class EntityCreatesScheduledOrchestration
+{
+    [Function("EntityCreatesScheduledOrchestrationOrchestrator_HttpStart")]
+    public static async Task<HttpResponseData> HttpStartScheduled(
+        [HttpTrigger(AuthorizationLevel.Anonymous, "get", "post")] HttpRequestData req,
+        [DurableClient] DurableTaskClient client,
+        FunctionContext executionContext,
+        int scheduledStartDelaySeconds)
+    {
+        ILogger logger = executionContext.GetLogger("EntityCreatesScheduledOrchestrationOrchestrator_HttpStart");
+
+        // Function input comes from the request content.
+        string instanceId = await client.ScheduleNewOrchestrationInstanceAsync(
+            nameof(EntityCreatesScheduledOrchestrationOrchestrator), input: scheduledStartDelaySeconds);
+
+        logger.LogInformation("Started orchestration with ID = '{instanceId}'.", instanceId);
+
+        // Returns an HTTP 202 response with an instance management payload.
+        // See https://learn.microsoft.com/azure/azure-functions/durable/durable-functions-http-api#start-orchestration
+        return await client.CreateCheckStatusResponseAsync(req, instanceId);
+    }
+
+    [Function(nameof(EntityCreatesScheduledOrchestrationOrchestrator))]
+    public static async Task<string> EntityCreatesScheduledOrchestrationOrchestrator(
+        [OrchestrationTrigger] TaskOrchestrationContext context)
+    {
+        var entityId = new EntityInstanceId(nameof(SubOrchestratorTriggerEntity), "singleton");
+        var scheduledOrchestrationInstanceId = await context.Entities.CallEntityAsync<string>(entityId, nameof(SubOrchestratorTriggerEntity.Call), context.GetInput<int>());
+        return scheduledOrchestrationInstanceId;
+    }
+
+    [Function(nameof(ScheduledOrchestrationSubOrchestrator))]
+    public static string ScheduledOrchestrationSubOrchestrator([OrchestrationTrigger] TaskOrchestrationContext context, string? _)
+    {
+        return "Success";
+    }
+}
+
+
+public class SubOrchestratorTriggerEntity: TaskEntity<string>
+{
+    public string Call(int delaySeconds)
+    {
+        var options = new StartOrchestrationOptions(null, DateTime.UtcNow.AddSeconds(delaySeconds));
+        var instanceId = this.Context.ScheduleNewOrchestration(nameof(EntityCreatesScheduledOrchestration.ScheduledOrchestrationSubOrchestrator), null, options);
+        return instanceId;
+    }
+
+    protected override string InitializeState(TaskEntityOperation entityOperation)
+    {
+        return string.Empty;
+    }
+
+    [Function(nameof(SubOrchestratorTriggerEntity))]
+    public Task RunEntityAsync([EntityTrigger] TaskEntityDispatcher dispatcher)
+    {
+        return dispatcher.DispatchAsync(this);
+    }
+}

test/e2e/Tests/Helpers/DurableHelpers.cs

@@ -18,18 +18,24 @@ internal class DurableHelpers
 
     internal class OrchestrationStatusDetails
     {
+        public string InstanceId { get; set; } = string.Empty;
         public string RuntimeStatus { get; set; } = string.Empty;
         public string Input { get; set; } = string.Empty;
         public string Output { get; set; } = string.Empty;
         public DateTime CreatedTime { get; set; }
         public DateTime LastUpdatedTime { get; set; }
         public OrchestrationStatusDetails(string statusQueryResponse)
         {
+            if (string.IsNullOrEmpty(statusQueryResponse))
+            {
+                return;
+            }
             JsonNode? statusQueryJsonNode = JsonNode.Parse(statusQueryResponse);
             if (statusQueryJsonNode == null)
             {
                 return;
             }
+            this.InstanceId = statusQueryJsonNode["instanceId"]?.GetValue<string>() ?? string.Empty;
             this.RuntimeStatus = statusQueryJsonNode["runtimeStatus"]?.GetValue<string>() ?? string.Empty;
             this.Input = statusQueryJsonNode["input"]?.ToString() ?? string.Empty;
             this.Output = statusQueryJsonNode["output"]?.ToString() ?? string.Empty;

test/e2e/Tests/Tests/HelloCitiesTest.cs

@@ -20,20 +20,6 @@ public HttpEndToEndTests(FunctionAppFixture fixture, ITestOutputHelper testOutpu
         this.output = testOutputHelper;
     }
 
-    // Due to some kind of asynchronous race condition in XUnit, when running these tests in pipelines,
-    // the output may be disposed before the message is written. Just ignore these types of errors for now. 
-    private void WriteOutput(string message)
-    {
-        try
-        {
-            this.output.WriteLine(message);
-        }
-        catch
-        {
-            // Ignore
-        }
-    }
-
     [Theory]
     [InlineData("HelloCities", HttpStatusCode.Accepted, "Hello Tokyo!")]
     public async Task HttpTriggerTests(string orchestrationName, HttpStatusCode expectedStatusCode, string partialExpectedOutput)
@@ -48,47 +34,4 @@ public async Task HttpTriggerTests(string orchestrationName, HttpStatusCode expe
         var orchestrationDetails = await DurableHelpers.GetRunningOrchestrationDetailsAsync(statusQueryGetUri);
         Assert.Contains(partialExpectedOutput, orchestrationDetails.Output);
     }
-
-    [Theory]
-    [InlineData("HelloCities_HttpStart_Scheduled", 5, HttpStatusCode.Accepted)]
-    [InlineData("HelloCities_HttpStart_Scheduled", -5, HttpStatusCode.Accepted)]
-    [Trait("PowerShell", "Skip")] // Scheduled orchestrations not implemented in PowerShell
-    public async Task ScheduledStartTests(string functionName, int startDelaySeconds, HttpStatusCode expectedStatusCode)
-    {
-        var testStartTime = DateTime.UtcNow;
-        var scheduledStartTime = testStartTime + TimeSpan.FromSeconds(startDelaySeconds);
-        string urlQueryString = $"?ScheduledStartTime={scheduledStartTime.ToString("o")}";
-
-        using HttpResponseMessage response = await HttpHelpers.InvokeHttpTrigger(functionName, urlQueryString);
-
-        string statusQueryGetUri = await DurableHelpers.ParseStatusQueryGetUriAsync(response);
-
-        Assert.Equal(expectedStatusCode, response.StatusCode);
-
-        if (scheduledStartTime > DateTime.UtcNow + TimeSpan.FromSeconds(1))
-        {
-            if (this.fixture.functionLanguageLocalizer.GetLanguageType() == LanguageType.DotnetIsolated || 
-                this.fixture.functionLanguageLocalizer.GetLanguageType() == LanguageType.Java)
-            {
-                await DurableHelpers.WaitForOrchestrationStateAsync(statusQueryGetUri, "Pending", 30);
-            }
-            else
-            {
-                // Scheduled orchestrations are not properly implemented in the other languages - however, 
-                // this test has been implemented using timers in the orchestration instead.
-                await DurableHelpers.WaitForOrchestrationStateAsync(statusQueryGetUri, "Running", 30);
-            }
-        }
-
-        await DurableHelpers.WaitForOrchestrationStateAsync(statusQueryGetUri, "Completed", Math.Max(startDelaySeconds, 0) + 30);
-
-        // This +2s should not be necessary - however, experimentally the orchestration may run up to ~1 second before the scheduled time.
-        // It is unclear currently whether this is a bug where orchestrations run early, or a clock difference/error,
-        // but leaving this logic in for now until further investigation.
-        Assert.True(DateTime.UtcNow + TimeSpan.FromSeconds(2) >= scheduledStartTime);
-
-        var finalOrchestrationDetails = await DurableHelpers.GetRunningOrchestrationDetailsAsync(statusQueryGetUri);
-        WriteOutput($"Last updated at {finalOrchestrationDetails.LastUpdatedTime}, scheduled to complete at {scheduledStartTime}");
-        Assert.True(finalOrchestrationDetails.LastUpdatedTime + TimeSpan.FromSeconds(2) >= scheduledStartTime);
-    }
 }

test/e2e/Tests/Tests/ScheduledOrchestrationTests.cs

@@ -0,0 +1,125 @@
+// Copyright (c) .NET Foundation. All rights reserved.
+// Licensed under the MIT License. See License.txt in the project root for license information.
+
+using System.Net;
+using Xunit;
+using Xunit.Abstractions;
+
+namespace Microsoft.Azure.Durable.Tests.DotnetIsolatedE2E;
+
+[Collection(Constants.FunctionAppCollectionName)]
+public class ScheduledOrchestrationTests
+{
+    private readonly FunctionAppFixture fixture;
+    private readonly ITestOutputHelper output;
+
+    public ScheduledOrchestrationTests(FunctionAppFixture fixture, ITestOutputHelper testOutputHelper)
+    {
+        this.fixture = fixture;
+        this.fixture.TestLogs.UseTestLogger(testOutputHelper);
+        this.output = testOutputHelper;
+    }
+
+    // Due to some kind of asynchronous race condition in XUnit, when running these tests in pipelines,
+    // the output may be disposed before the message is written. Just ignore these types of errors for now. 
+    private void WriteOutput(string message)
+    {
+        try
+        {
+            this.output.WriteLine(message);
+        }
+        catch
+        {
+            // Ignore
+        }
+    }
+
+    [Theory]
+    [InlineData("HelloCities_HttpStart_Scheduled", 5, HttpStatusCode.Accepted)]
+    [InlineData("HelloCities_HttpStart_Scheduled", -5, HttpStatusCode.Accepted)]
+    [Trait("PowerShell", "Skip")] // Scheduled orchestrations not implemented in PowerShell
+    public async Task ScheduledStartTests(string functionName, int startDelaySeconds, HttpStatusCode expectedStatusCode)
+    {
+        var testStartTime = DateTime.UtcNow;
+        var scheduledStartTime = testStartTime + TimeSpan.FromSeconds(startDelaySeconds);
+        string urlQueryString = $"?ScheduledStartTime={scheduledStartTime.ToString("o")}";
+
+        using HttpResponseMessage response = await HttpHelpers.InvokeHttpTrigger(functionName, urlQueryString);
+
+        string statusQueryGetUri = await DurableHelpers.ParseStatusQueryGetUriAsync(response);
+
+        Assert.Equal(expectedStatusCode, response.StatusCode);
+
+        if (scheduledStartTime > DateTime.UtcNow + TimeSpan.FromSeconds(1))
+        {
+            if (this.fixture.functionLanguageLocalizer.GetLanguageType() == LanguageType.DotnetIsolated ||
+                this.fixture.functionLanguageLocalizer.GetLanguageType() == LanguageType.Java)
+            {
+                // This line will throw if the orchestration goes to a terminal state before reaching "Pending",
+                // ensuring that any scheduled orchestrations that run immediately fail the test.
+                await DurableHelpers.WaitForOrchestrationStateAsync(statusQueryGetUri, "Pending", 30);
+            }
+            else
+            {
+                // Scheduled orchestrations are not properly implemented in the other languages - however, 
+                // this test has been implemented using timers in the orchestration instead.
+                await DurableHelpers.WaitForOrchestrationStateAsync(statusQueryGetUri, "Running", 30);
+            }
+        }
+
+        await DurableHelpers.WaitForOrchestrationStateAsync(statusQueryGetUri, "Completed", Math.Max(startDelaySeconds, 0) + 30);
+
+        // This +2s should not be necessary - however, experimentally the orchestration may run up to ~1 second before the scheduled time.
+        // It is unclear currently whether this is a bug where orchestrations run early, or a clock difference/error,
+        // but leaving this logic in for now until further investigation.
+        Assert.True(DateTime.UtcNow + TimeSpan.FromSeconds(2) >= scheduledStartTime);
+
+        var finalOrchestrationDetails = await DurableHelpers.GetRunningOrchestrationDetailsAsync(statusQueryGetUri);
+        WriteOutput($"Last updated at {finalOrchestrationDetails.LastUpdatedTime}, scheduled to complete at {scheduledStartTime}");
+        Assert.True(finalOrchestrationDetails.LastUpdatedTime + TimeSpan.FromSeconds(2) >= scheduledStartTime);
+    }
+
+    [Theory]
+    [InlineData("EntityCreatesScheduledOrchestrationOrchestrator_HttpStart", 5, HttpStatusCode.Accepted)]
+    [InlineData("EntityCreatesScheduledOrchestrationOrchestrator_HttpStart", -5, HttpStatusCode.Accepted)]
+    [Trait("PowerShell", "Skip")] // Durable Entities not yet implemented in PowerShell
+    [Trait("Java", "Skip")] // Durable Entities not yet implemented in Java
+    [Trait("Python", "Skip")] // Durable Entities do not support the "schedule new orchestration" action in Python
+    [Trait("Node", "Skip")] // Durable Entities do not support the "schedule new orchestration" action in Node
+    [Trait("MSSQL", "Skip")] // Durable Entities are not supported in MSSQL for out-of-proc (see https://github.com/microsoft/durabletask-mssql/issues/205)
+    public async Task ScheduledStartFromEntitiesTests(string functionName, int startDelaySeconds, HttpStatusCode expectedStatusCode)
+    {
+        var testStartTime = DateTime.UtcNow;
+        var scheduledStartTime = testStartTime + TimeSpan.FromSeconds(startDelaySeconds);
+        string urlQueryString = $"?scheduledStartDelaySeconds={startDelaySeconds}";
+
+        using HttpResponseMessage response = await HttpHelpers.InvokeHttpTrigger(functionName, urlQueryString);
+
+        string statusQueryGetUri = await DurableHelpers.ParseStatusQueryGetUriAsync(response);
+
+        Assert.Equal(expectedStatusCode, response.StatusCode);
+        await DurableHelpers.WaitForOrchestrationStateAsync(statusQueryGetUri, "Completed", Math.Max(startDelaySeconds, 0) + 30);
+        var schedulerOrchestrationDetails = await DurableHelpers.GetRunningOrchestrationDetailsAsync(statusQueryGetUri);
+        string subOrchestratorInstanceId = schedulerOrchestrationDetails.Output;
+
+        string subOrchestratorStatusQueryGetUri = statusQueryGetUri.ToLower().Replace(schedulerOrchestrationDetails.InstanceId.ToLower(), subOrchestratorInstanceId);
+
+        if (scheduledStartTime > DateTime.UtcNow + TimeSpan.FromSeconds(1))
+        {
+            // This line will throw if the orchestration goes to a terminal state before reaching "Pending",
+            // ensuring that any scheduled orchestrations that run immediately fail the test.
+            await DurableHelpers.WaitForOrchestrationStateAsync(subOrchestratorStatusQueryGetUri, "Pending", 30);
+        }
+
+        await DurableHelpers.WaitForOrchestrationStateAsync(subOrchestratorStatusQueryGetUri, "Completed", Math.Max(startDelaySeconds, 0) + 30);
+
+        // This +2s should not be necessary - however, experimentally the orchestration may run up to ~1 second before the scheduled time.
+        // It is unclear currently whether this is a bug where orchestrations run early, or a clock difference/error,
+        // but leaving this logic in for now until further investigation.
+        Assert.True(DateTime.UtcNow + TimeSpan.FromSeconds(2) >= scheduledStartTime);
+
+        var subOrchestrationDetails = await DurableHelpers.GetRunningOrchestrationDetailsAsync(subOrchestratorStatusQueryGetUri);
+        Assert.True(subOrchestrationDetails.LastUpdatedTime + TimeSpan.FromSeconds(2) >= scheduledStartTime);
+        Assert.Equal("Success", subOrchestrationDetails.Output);
+    }
+}