Repository: Azure/azure-functions-durable-js
Pull request #108 (2019-10-23 18:15:28)

Fix creating sub orchestrations without specifying instance ids
Currently, only the first sub orchestration created without specifying
an instance id will ever be marked as completed. This fix aims to
address that. Addresses issue #54.

The new approach should also more aggressively find non-deterministic replays, and added some tests to emulate these errors.


Patch:
diff --git a/.vscode/launch.json b/.vscode/launch.json
index 3ce4166..7097915 100644
--- a/.vscode/launch.json
+++ b/.vscode/launch.json
@@ -4,6 +4,8 @@
     // For more information, visit: https://go.microsoft.com/fwlink/?linkid=830387
     "version": "0.2.0",
     "configurations": [
+
+
         {
             "type": "node",
             "request": "launch",
@@ -55,6 +57,28 @@
                 "${workspaceFolder}/lib/**"
             ],
             "preLaunchTask": "build"
+        },
+        {
+            "type": "node",
+            "request": "launch",
+            "name": "Mocha Tests Debug",
+            "program": "${workspaceFolder}/node_modules/mocha/bin/_mocha",
+            "args": [
+                "-u",
+                "tdd",
+                "--colors",
+                "${workspaceFolder}/lib/test/**/**-spec.js",
+                "-g",
+                ".*",
+                "--timeout",
+                "300000"
+            ],
+            "internalConsoleOptions": "openOnSessionStart",
+            "sourceMaps": true,
+            "outFiles": [
+                "${workspaceFolder}/lib/**"
+            ],
+            "preLaunchTask": "build"
         }
     ]
 }
diff --git a/src/orchestrator.ts b/src/orchestrator.ts
index a2c0391..1c7948a 100644
--- a/src/orchestrator.ts
+++ b/src/orchestrator.ts
@@ -19,6 +19,7 @@ export class Orchestrator {
     private currentUtcDateTime: Date;
     private customStatus: unknown;
     private newGuidCounter: number;
+    private subOrchestratorCounter: number;
 
     constructor(public fn: (context: IOrchestrationFunctionContext) => IterableIterator<unknown>) { }
 
@@ -45,8 +46,9 @@ export class Orchestrator {
             "The orchestrator can not execute without an OrchestratorStarted event.");
         this.currentUtcDateTime = new Date(decisionStartedEvent.Timestamp);
 
-        // Reset newGuidCounter
+        // Reset counters
         this.newGuidCounter = 0;
+        this.subOrchestratorCounter = 0;
 
         // Create durable orchestration context
         context.df = {
@@ -251,12 +253,16 @@ export class Orchestrator {
     }
 
     private callSubOrchestrator(state: HistoryEvent[], name: string, input?: unknown, instanceId?: string): Task {
-        const newAction = new CallSubOrchestratorAction(name, instanceId, input);
+        if (!name) {
+            throw new Error("A sub-orchestration function name must be provided when attempting to create a suborchestration");
+        }
 
+        const newAction = new CallSubOrchestratorAction(name, instanceId, input);
         const subOrchestratorCreated = this.findSubOrchestrationInstanceCreated(state, name, instanceId);
         const subOrchestratorCompleted = this.findSubOrchestrationInstanceCompleted(state, subOrchestratorCreated);
         const subOrchestratorFailed = this.findSubOrchestrationInstanceFailed(state, subOrchestratorCreated);
-        this.setProcessed([subOrchestratorCreated, subOrchestratorCompleted]);
+
+        this.setProcessed([subOrchestratorCreated, subOrchestratorCompleted, subOrchestratorFailed]);
 
         if (subOrchestratorCompleted) {
             const result = this.parseHistoryEvent(subOrchestratorCompleted);
@@ -295,6 +301,10 @@ export class Orchestrator {
         input?: unknown,
         instanceId?: string)
         : Task {
+        if (!name) {
+            throw new Error("A sub-orchestration function name must be provided when attempting to create a suborchestration");
+        }
+
         const newAction = new CallSubOrchestratorWithRetryAction(name, retryOptions, input, instanceId);
 
         for (let attempt = 1; attempt <= retryOptions.maxNumberOfAttempts; attempt++) {
@@ -586,7 +596,7 @@ export class Orchestrator {
     }
 
     /* Returns undefined if not found. */
-    private findRetryTimer(state: HistoryEvent[], failedTask: HistoryEvent): TimerCreatedEvent {
+    private findRetryTimer(state: HistoryEvent[], failedTask: HistoryEvent | undefined): TimerCreatedEvent | undefined {
         const returnValue = failedTask
             ? state.filter((val: HistoryEvent, index: number, array: HistoryEvent[]) => {
                 const failedTaskIndex = array.indexOf(failedTask);
@@ -602,44 +612,67 @@ export class Orchestrator {
         state: HistoryEvent[],
         name: string,
         instanceId: string | undefined)
-        : SubOrchestrationInstanceCreatedEvent {
-        const returnValue = name
-            ? state.filter((val: HistoryEvent) => {
-                return val.EventType === HistoryEventType.SubOrchestrationInstanceCreated
-                    && (val as SubOrchestrationInstanceCreatedEvent).Name === name
-                    && (val as SubOrchestrationInstanceCreatedEvent).InstanceId === instanceId
-                    && !val.IsProcessed;
-            })[0]
-            : undefined;
-        return returnValue as SubOrchestrationInstanceCreatedEvent;
+        : SubOrchestrationInstanceCreatedEvent | undefined {
+        const matches = state.filter((val: HistoryEvent) => {
+            return val.EventType === HistoryEventType.SubOrchestrationInstanceCreated
+                && !val.IsProcessed;
+        });
+
+        if (matches.length === 0) {
+            return undefined;
+        }
+
+        this.subOrchestratorCounter++;
+
+        // Grab the first unprocessed sub orchestration creation event and verify that
+        // it matches the same function name and instance id if provided. If not, we know that
+        // we have nondeterministic behavior, because the callSubOrchestrator*() methods were not
+        // called in the same order this replay that they were scheduled in.
+        const returnValue = matches[0] as SubOrchestrationInstanceCreatedEvent;
+        if (returnValue.Name !== name) {
+            throw new Error(`The sub-orchestration call (n = ${this.subOrchestratorCounter}) should be executed with a function name of ${returnValue.Name} instead of the provided function name of ${name}. Check your code for non-deterministic behavior.`);
+        }
+
+        if (instanceId && returnValue.InstanceId !== instanceId) {
+            throw new Error(`The sub-orchestration call (n = ${this.subOrchestratorCounter}) should be executed with an instance id of ${returnValue.InstanceId} instead of the provided instance id of ${instanceId}. Check your code for non-deterministic behavior.`);
+        }
+        return returnValue;
     }
 
     /* Returns undefined if not found. */
     private findSubOrchestrationInstanceCompleted(
         state: HistoryEvent[],
-        createdSubOrch: SubOrchestrationInstanceCreatedEvent)
-        : SubOrchestrationInstanceCompletedEvent {
-        const returnValue = createdSubOrch
-            ? state.filter((val: HistoryEvent) => {
+        createdSubOrch: SubOrchestrationInstanceCreatedEvent | undefined)
+        : SubOrchestrationInstanceCompletedEvent | undefined {
+        if (createdSubOrch === undefined) {
+            return undefined;
+        }
+
+        const matches = state.filter((val: HistoryEvent) => {
                 return val.EventType === HistoryEventType.SubOrchestrationInstanceCompleted
-                    && (val as SubOrchestrationInstanceCompletedEvent).TaskScheduledId === createdSubOrch.EventId;
-            })[0]
-            : undefined;
-        return returnValue as SubOrchestrationInstanceCompletedEvent;
+                    && (val as SubOrchestrationInstanceCompletedEvent).TaskScheduledId === createdSubOrch.EventId
+                    && !val.IsProcessed;
+            });
+
+        return (matches.length > 0) ? matches[0] as SubOrchestrationInstanceCompletedEvent : undefined;
     }
 
     /* Returns undefined if not found. */
     private findSubOrchestrationInstanceFailed(
         state: HistoryEvent[],
-        createdSubOrchInstance: SubOrchestrationInstanceCreatedEvent)
-        : SubOrchestrationInstanceFailedEvent {
-        const returnValue = createdSubOrchInstance
-            ? state.filter((val: HistoryEvent) => {
-                return val.EventType === HistoryEventType.SubOrchestrationInstanceFailed
-                    && (val as SubOrchestrationInstanceFailedEvent).TaskScheduledId === createdSubOrchInstance.EventId;
-            })[0]
-            : undefined;
-        return returnValue as SubOrchestrationInstanceFailedEvent;
+        createdSubOrchInstance: SubOrchestrationInstanceCreatedEvent | undefined)
+        : SubOrchestrationInstanceFailedEvent | undefined {
+            if (createdSubOrchInstance === undefined) {
+                return undefined;
+            }
+
+            const matches = state.filter((val: HistoryEvent) => {
+                    return val.EventType === HistoryEventType.SubOrchestrationInstanceFailed
+                        && (val as SubOrchestrationInstanceFailedEvent).TaskScheduledId === createdSubOrchInstance.EventId
+                        && !val.IsProcessed;
+                });
+
+            return (matches.length > 0) ? matches[0] as SubOrchestrationInstanceFailedEvent : undefined;
     }
 
     /* Returns undefined if not found. */
@@ -688,7 +721,7 @@ export class Orchestrator {
     }
 
     /* Returns undefined if not found. */
-    private findTimerFired(state: HistoryEvent[], createdTimer: HistoryEvent): TimerFiredEvent {
+    private findTimerFired(state: HistoryEvent[], createdTimer: TimerCreatedEvent | undefined): TimerFiredEvent | undefined {
         const returnValue = createdTimer
             ? state.filter((val: HistoryEvent) => {
                 return val.EventType === HistoryEventType.TimerFired


Test patch:
diff --git a/test/integration/orchestrator-spec.ts b/test/integration/orchestrator-spec.ts
index 553dc61..f506a91 100644
--- a/test/integration/orchestrator-spec.ts
+++ b/test/integration/orchestrator-spec.ts
@@ -840,6 +840,98 @@ describe("Orchestrator", () => {
             );
         });
 
+        it("Succesfully runs multiple suborchestrator function with no instanceId", async () => {
+            const orchestrator = TestOrchestrations.MultipleSubOrchestratorNoSubId;
+            const name = "World";
+            const id = uuidv1();
+            const mockContext = new MockContext({
+                context: new DurableOrchestrationBindingInfo(
+                    TestHistories.GetMultipleSubOrchestratorNoIdsSubOrchestrationsFinished(
+                        moment.utc().toDate(),
+                        orchestrator,
+                        ["SayHelloWithActivity", "SayHelloInline", "SayHelloWithActivity", "SayHelloInline"],
+                        name,
+                    ),
+                    name,
+                    id,
+                ),
+            });
+
+            orchestrator(mockContext);
+
+            expect(mockContext.doneValue).to.be.deep.equal(
+                new OrchestratorState({
+                    isDone: true,
+                    output: [`Hello, ${name}_SayHelloWithActivity_0!`, `Hello, ${name}_SayHelloInline_1!`, `Hello, ${name}_SayHelloWithActivity_2!`, `Hello, ${name}_SayHelloInline_3!`],
+                    actions: [
+                                [
+                                    new CallSubOrchestratorAction("SayHelloWithActivity", undefined, `${name}_SayHelloWithActivity_0`),
+                                    new CallSubOrchestratorAction("SayHelloInline", undefined, `${name}_SayHelloInline_1`),
+                                    new CallSubOrchestratorAction("SayHelloWithActivity", undefined, `${name}_SayHelloWithActivity_2`),
+                                    new CallSubOrchestratorAction("SayHelloInline", undefined, `${name}_SayHelloInline_3`),
+                                ],
+                            ],
+                }),
+            );
+        });
+
+        it("replay does not match history (mismatched suborchestration name) and throws error.", async () => {
+            const orchestrator = TestOrchestrations.MultipleSubOrchestratorNoSubId;
+            const name = "World";
+            const id = uuidv1();
+            const mockContext = new MockContext({
+                context: new DurableOrchestrationBindingInfo(
+                    TestHistories.GetMultipleSubOrchestratorNoIdsSubOrchestrationsFinished(
+                        moment.utc().toDate(),
+                        orchestrator,
+                        // The order in the sample suborchestrator is ["SayHelloWithActivity", "SayHelloInline", "SayHelloWithActivity", "SayHelloInline"]
+                        ["SayHelloInline", "SayHelloWithActivity", "SayHelloWithActivity", "SayHelloInline"],
+                        name,
+                    ),
+                    name,
+                    id,
+                ),
+            });
+
+            orchestrator(mockContext);
+
+            const expectedErr = "The sub-orchestration call (n = 1) should be executed with a function name of SayHelloInline instead of the provided function name of SayHelloWithActivity. Check your code for non-deterministic behavior.";
+
+            expect(mockContext.doneValue!.error).to
+                .include(expectedErr);
+
+            expect(mockContext.err!.toString()).to.include(expectedErr);
+        });
+
+        it("replay does not match history (mismatched suborchestration instance id) and throws error.", async () => {
+            const orchestrator = TestOrchestrations.SayHelloWithSubOrchestrator;
+            const name = "World";
+            const id = uuidv1();
+            const subId = id + ":1";
+            const mockContext = new MockContext({
+                context: new DurableOrchestrationBindingInfo(
+                    TestHistories.GetSayHelloWithSubOrchestratorReplayOne(
+                        moment.utc().toDate(),
+                        orchestrator,
+                        "SayHelloWithActivity",
+                        subId,
+                        name,
+                    ),
+                    name,
+                    id,
+                ),
+            });
+
+            orchestrator(mockContext);
+
+            const expectedErr = `The sub-orchestration call (n = 1) should be executed with an instance id of ${subId} instead of the provided instance id of ${id}:0. Check your code for non-deterministic behavior.`;
+
+            expect(mockContext.doneValue!.error).to
+                .include(expectedErr);
+
+            expect(mockContext.err!.toString()).to.include(expectedErr);
+        });
+
         it("handles a completed suborchestrator function", async () => {
             const orchestrator = TestOrchestrations.SayHelloWithSubOrchestrator;
             const name = "World";
@@ -902,6 +994,7 @@ describe("Orchestrator", () => {
                     [ new CallSubOrchestratorAction("SayHelloWithActivity", childId, name) ],
                 ],
             });
+
             expect(mockContext.doneValue!.error).to
                 .include(expectedErr);
 
diff --git a/test/testobjects/TestOrchestrations.ts b/test/testobjects/TestOrchestrations.ts
index 1aa7661..2b9dcea 100644
--- a/test/testobjects/TestOrchestrations.ts
+++ b/test/testobjects/TestOrchestrations.ts
@@ -137,6 +137,17 @@ export class TestOrchestrations {
         return output;
     });
 
+    public static MultipleSubOrchestratorNoSubId: any = df.orchestrator(function*(context: any) {
+        const input = context.df.getInput();
+        const subOrchName1 = "SayHelloWithActivity";
+        const subOrchName2 = "SayHelloInline";
+        const output = context.df.callSubOrchestrator(subOrchName1, `${input}_${subOrchName1}_0`);
+        const output2 = context.df.callSubOrchestrator(subOrchName2, `${input}_${subOrchName2}_1`);
+        const output3 = context.df.callSubOrchestrator(subOrchName1, `${input}_${subOrchName1}_2`);
+        const output4 = context.df.callSubOrchestrator(subOrchName2, `${input}_${subOrchName2}_3`);
+        return yield context.df.Task.all([output, output2, output3, output4]);
+    });
+
     public static SayHelloWithSubOrchestratorRetry: any = df.orchestrator(function*(context: any) {
         const input = context.df.getInput();
         const childId = context.df.instanceId + ":0";
diff --git a/test/testobjects/testhistories.ts b/test/testobjects/testhistories.ts
index 57fab89..9967ddf 100644
--- a/test/testobjects/testhistories.ts
+++ b/test/testobjects/testhistories.ts
@@ -1480,6 +1480,78 @@ export class TestHistories {
         ];
     }
 
+    // Covers the scenario for TestOrchestrations.MultipleSubOrchestratorNoSubId in which
+    // all of the scheduled sub orchestrations are completed around the same time and processed
+    // in the same orchestration replay.
+    public static GetMultipleSubOrchestratorNoIdsSubOrchestrationsFinished(
+        firstTimestamp: Date,
+        orchestratorName: string,
+        subOrchestratorNames: string[],
+        input: string)
+        : HistoryEvent[] {
+        const firstMoment = moment(firstTimestamp);
+
+        const baseSubInstanceId = "dummy-unique-id";
+        const historyEvents =  [
+            new OrchestratorStartedEvent(
+                {
+                    eventId: -1,
+                    timestamp: firstTimestamp,
+                    isPlayed: false,
+                },
+            ),
+            new ExecutionStartedEvent(
+                {
+                    eventId: -1,
+                    timestamp: firstTimestamp,
+                    isPlayed: true,
+                    name: orchestratorName,
+                    input,
+                },
+            )];
+        for (let i = 0; i < subOrchestratorNames.length; i++) {
+            historyEvents.push(new SubOrchestrationInstanceCreatedEvent(
+                {
+                    eventId: i,
+                    timestamp: firstTimestamp,
+                    isPlayed: false,
+                    name: subOrchestratorNames[i],
+                    input: `${input}_${subOrchestratorNames[i]}_${i}`,
+                    instanceId: `${baseSubInstanceId}_${i}`,
+                },
+            ));
+        }
+        historyEvents.push(
+            new OrchestratorCompletedEvent(
+                {
+                    eventId: -1,
+                    timestamp: firstTimestamp,
+                    isPlayed: false,
+                },
+            ),
+            new OrchestratorStartedEvent(
+                {
+                    eventId: -1,
+                    timestamp: firstMoment.add(1, "s").toDate(),
+                    isPlayed: false,
+                },
+            ));
+
+        for (let i = 0; i < subOrchestratorNames.length; i++) {
+            historyEvents.push(new SubOrchestrationInstanceCompletedEvent(
+                {
+                    eventId: -1,
+                    timestamp: firstMoment.add(1, "s").toDate(),
+                    isPlayed: false,
+                    result: JSON.stringify(`Hello, ${input}_${subOrchestratorNames[i]}_${i}!`),
+                    taskScheduledId: i,
+                },
+            ));
+        }
+
+        return historyEvents;
+    }
+
     public static GetSayHelloWithSubOrchestratorFail(
         firstTimestamp: Date,
         orchestratorName: string,