Repository: Azure/azure-functions-durable-js
Pull request #100 (2019-08-27 20:26:15)

CurrentUtcDateTime advancer uses last good currentUtcDateTime value if no new value found.
Some customers have been experiencing their orchestrators intermittently crashing with the following stack trace:

```
TypeError: Cannot read property \'Timestamp\' of undefined
    at state.find (C:\Dev\azure-functions-durable-js\lib\src\orchestrator.js:92:60)
    at Array.find (<anonymous>)
    at Orchestrator.<anonymous> (C:\Dev\azure-functions-durable-js\lib\src\orchestrator.js:91:50)
    at Generator.next (<anonymous>)
    at C:\Dev\azure-functions-durable-js\lib\src\orchestrator.js:7:71
    at new Promise (<anonymous>)
    at __awaiter (C:\Dev\azure-functions-durable-js\lib\src\orchestrator.js:3:12)
    at Orchestrator.handle (C:\Dev\azure-functions-durable-js\lib\src\orchestrator.js:22:16)
    at C:\Dev\azure-functions-durable-js\lib\src\shim.js:7:9
    at Object.<anonymous> (C:\Dev\azure-functions-durable-js\lib\test\integration\orchestrator-spec.js:102:13)
    at Generator.next (<anonymous>)
    at C:\Dev\azure-functions-durable-js\lib\test\integration\orchestrator-spec.js:7:71
    at new Promise (<anonymous>)
    at __awaiter (C:\Dev\azure-functions-durable-js\lib\test\integration\orchestrator-spec.js:3:12)
    at Context.it (C:\Dev\azure-functions-durable-js\lib\test\integration\orchestrator-spec.js:96:98)
    at callFn (C:\Dev\azure-functions-durable-js\node_modules\mocha\lib\runnable.js:372:21)
    at Test.Runnable.run (C:\Dev\azure-functions-durable-js\node_modules\mocha\lib\runnable.js:364:7)
    at Runner.runTest (C:\Dev\azure-functions-durable-js\node_modules\mocha\lib\runner.js:455:10)
    at C:\Dev\azure-functions-durable-js\node_modules\mocha\lib\runner.js:573:12
    at next (C:\Dev\azure-functions-durable-js\node_modules\mocha\lib\runner.js:369:14)
    at C:\Dev\azure-functions-durable-js\node_modules\mocha\lib\runner.js:379:7
    at next (C:\Dev\azure-functions-durable-js\node_modules\mocha\lib\runner.js:303:14)
    at Immediate._onImmediate (C:\Dev\azure-functions-durable-js\node_modules\mocha\lib\runner.js:347:5)
    at runCallback (timers.js:705:18)
    at tryOnImmediate (timers.js:676:5)
    at processImmediate (timers.js:658:5)
```

@cliffkoh and I discovered the root cause of this was that under certain conditions (orchestrator + history event sequence), the portion of `orchestrator.ts` that advances `currentUtcDateTime` can run out of history events. In this case its search returns undefined, causing the above error when it tries to access <HistoryEvent>.timeStamp. This fix uses the last good currentUtcDateTime value under these conditions, allowing execution to continue.


Patch:
diff --git a/src/orchestrator.ts b/src/orchestrator.ts
index b4ce85a..ee1b91a 100644
--- a/src/orchestrator.ts
+++ b/src/orchestrator.ts
@@ -115,12 +115,12 @@ export class Orchestrator {
                     return;
                 }
 
-                decisionStartedEvent = state.find((e) =>
+                const newDecisionStartedEvent = state.find((e) =>
                     e.EventType === HistoryEventType.OrchestratorStarted &&
                     e.Timestamp > decisionStartedEvent.Timestamp);
-                context.df.currentUtcDateTime = this.currentUtcDateTime = decisionStartedEvent
-                    ? new Date(decisionStartedEvent.Timestamp)
-                    : undefined;
+
+                decisionStartedEvent = newDecisionStartedEvent || decisionStartedEvent;
+                context.df.currentUtcDateTime = this.currentUtcDateTime = new Date(decisionStartedEvent.Timestamp);
 
                 g = gen.next(partialResult ? partialResult.result : undefined);
             }


Test patch:
diff --git a/test/integration/orchestrator-spec.ts b/test/integration/orchestrator-spec.ts
index cfb78be..9c9a82c 100644
--- a/test/integration/orchestrator-spec.ts
+++ b/test/integration/orchestrator-spec.ts
@@ -12,8 +12,8 @@ import { TestHistories } from "../testobjects/testhistories";
 import { TestOrchestrations } from "../testobjects/TestOrchestrations";
 
 describe("Orchestrator", () => {
-    const falsyValues = [ false, 0, "", null, undefined, NaN ];  
-  
+    const falsyValues = [ false, 0, "", null, undefined, NaN ];
+
     it("handles a simple orchestration function (no activity functions)", async () => {
         const orchestrator = TestOrchestrations.SayHelloInline;
         const name = "World";
@@ -45,7 +45,7 @@ describe("Orchestrator", () => {
                     TestHistories.GetOrchestratorStart(
                         "PassThrough",
                         moment.utc().toDate(),
-                        falsyValue
+                        falsyValue,
                     ),
                     falsyValue,
                 ),
@@ -57,7 +57,7 @@ describe("Orchestrator", () => {
                     isDone: true,
                     actions: [],
                     output: falsyValue,
-                })
+                }),
             );
             if (isNaN(falsyValue as number)) {
                 expect(isNaN(mockContext.doneValue.output as number)).to.equal(true);
@@ -153,6 +153,24 @@ describe("Orchestrator", () => {
 
             expect(mockContext.df.currentUtcDateTime).to.be.deep.equal(nextTimestamp);
         });
+
+        it("uses existing currentUtcDateTime if OrchestratorStarted events are exhausted", async () => {
+            const orchestrator = TestOrchestrations.TimestampExhaustion;
+            const startTimestamp = moment.utc().toDate();
+
+            const mockContext = new MockContext({
+                context: new DurableOrchestrationBindingInfo(
+                    TestHistories.GetTimestampExhaustion(startTimestamp),
+                    { delayMergeUntilSecs: 1 },
+                ),
+            });
+
+            orchestrator(mockContext);
+
+            expect(mockContext.doneValue.error).to.equal(undefined);
+
+            expect(mockContext.err).to.equal(null);
+        });
     });
 
     describe("Error Handling", () => {
diff --git a/test/testobjects/TestOrchestrations.ts b/test/testobjects/TestOrchestrations.ts
index 9dcc306..bea13ad 100644
--- a/test/testobjects/TestOrchestrations.ts
+++ b/test/testobjects/TestOrchestrations.ts
@@ -134,6 +134,37 @@ export class TestOrchestrations {
         return output;
     });
 
+    /**
+     * This orchestrator and its corresponding history replicate conditions under
+     * which there are not sufficient OrchestratorStartedEvents in the history
+     * array to satisfy the currentUtcDateTime advancement logic.
+     */
+    public static TimestampExhaustion: any = df.orchestrator(function*(context: any) {
+        const payload = context.df.getInput();
+
+        yield context.df.callActivity("Merge");
+
+        if (payload.delayMergeUntilSecs) {
+            const now = new Date(context.df.currentUtcDateTime).getTime();
+            const fireAt = new Date(now + payload.delayMergeUntilSecs * 1000);
+            yield context.df.createTimer(fireAt);
+        }
+
+        let x = 0;
+        do {
+            const result = yield context.df.callActivity("CheckIfMerged");
+            const hasMerged = result.output;
+
+            if (hasMerged) {
+                return "Merge successful";
+            } else {
+                yield context.df.waitForExternalEvent("CheckPrForMerge");
+            }
+
+            x++;
+        } while (x < 10);
+    });
+
     public static WaitForExternalEvent: any = df.orchestrator(function*(context: any) {
         const name = yield context.df.waitForExternalEvent("start");
 
diff --git a/test/testobjects/testhistories.ts b/test/testobjects/testhistories.ts
index a111c4c..edcaeec 100644
--- a/test/testobjects/testhistories.ts
+++ b/test/testobjects/testhistories.ts
@@ -635,6 +635,306 @@ export class TestHistories {
         ];
     }
 
+    /**
+     * This history and its corresponding orchestrator replicate conditions under
+     * which there are not sufficient OrchestratorStartedEvents in the history
+     * array to satisfy the currentUtcDateTime advancement logic.
+     */
+    public static GetTimestampExhaustion(firstTimestamp: Date): HistoryEvent[] {
+        const firstTime = firstTimestamp.getTime();
+        const timestamps: Date[] = [];
+        for (let i = 0; i < 9; i++) {
+            timestamps[i] = new Date(firstTime + 1000 * i);
+        }
+
+        return [
+            new OrchestratorStartedEvent(
+                {
+                    eventId: -1,
+                    timestamp: timestamps[0],
+                    isPlayed: false,
+                },
+            ),
+            new ExecutionStartedEvent(
+                {
+                    eventId: -1,
+                    timestamp: timestamps[0],
+                    isPlayed: true,
+                    name: "TimestampExhaustion",
+                    input: JSON.stringify({ delayMergeUntilSecs: 1 }),
+                },
+            ),
+            new EventRaisedEvent(
+                {
+                    eventId: -1,
+                    timestamp: timestamps[0],
+                    isPlayed: true,
+                    name: "CheckPrForMerge",
+                    input: JSON.stringify({ value: 0 }),
+                },
+            ),
+            new TaskScheduledEvent(
+                {
+                    eventId: 0,
+                    timestamp: timestamps[0],
+                    isPlayed: false,
+                    name: "Merge",
+                },
+            ),
+            new OrchestratorCompletedEvent(
+                {
+                    eventId: -1,
+                    timestamp: timestamps[0],
+                    isPlayed: false,
+                },
+            ),
+            new OrchestratorStartedEvent(
+                {
+                    eventId: -1,
+                    timestamp: timestamps[1],
+                    isPlayed: false,
+                },
+            ),
+            new EventRaisedEvent(
+                {
+                    eventId: -1,
+                    timestamp: timestamps[1],
+                    isPlayed: true,
+                    name: "CheckPrForMerge",
+                    input: JSON.stringify({ value: 1 }),
+                },
+            ),
+            new OrchestratorCompletedEvent(
+                {
+                    eventId: -1,
+                    timestamp: timestamps[1],
+                    isPlayed: false,
+                },
+            ),
+            new OrchestratorStartedEvent(
+                {
+                    eventId: -1,
+                    timestamp: timestamps[2],
+                    isPlayed: false,
+                },
+            ),
+            new TaskCompletedEvent(
+                {
+                    eventId: -1,
+                    timestamp: timestamps[2],
+                    isPlayed: true,
+                    taskScheduledId: 0,
+                    result: JSON.stringify(""),
+                },
+            ),
+            new TimerCreatedEvent(
+                {
+                    eventId: 1,
+                    timestamp: timestamps[2],
+                    isPlayed: false,
+                    fireAt: timestamps[2],
+                },
+            ),
+            new OrchestratorCompletedEvent(
+                {
+                    eventId: -1,
+                    timestamp: timestamps[2],
+                    isPlayed: false,
+                },
+            ),
+            new OrchestratorStartedEvent(
+                {
+                    eventId: -1,
+                    timestamp: timestamps[3],
+                    isPlayed: false,
+                },
+            ),
+            new TimerFiredEvent(
+                {
+                    eventId: -1,
+                    timestamp: timestamps[3],
+                    isPlayed: true,
+                    fireAt: timestamps[2],
+                    timerId: 1,
+                },
+            ),
+            new TimerFiredEvent(
+                {
+                    eventId: -1,
+                    timestamp: timestamps[3],
+                    isPlayed: true,
+                    fireAt: timestamps[2],
+                    timerId: 1,
+                },
+            ),
+            new TaskScheduledEvent(
+                {
+                    eventId: 2,
+                    timestamp: timestamps[3],
+                    isPlayed: false,
+                    name: "CheckIfMerged",
+                },
+            ),
+            new OrchestratorCompletedEvent(
+                {
+                    eventId: -1,
+                    timestamp: timestamps[3],
+                    isPlayed: false,
+                },
+            ),
+            new OrchestratorStartedEvent(
+                {
+                    eventId: -1,
+                    timestamp: timestamps[4],
+                    isPlayed: false,
+                },
+            ),
+            new TaskCompletedEvent(
+                {
+                    eventId: -1,
+                    timestamp: timestamps[4],
+                    isPlayed: true,
+                    taskScheduledId: 2,
+                    result: JSON.stringify({ output: false }),
+                },
+            ),
+            new TaskScheduledEvent(
+                {
+                    eventId: 3,
+                    timestamp: timestamps[4],
+                    isPlayed: false,
+                    name: "CheckIfMerged",
+                },
+            ),
+            new OrchestratorCompletedEvent(
+                {
+                    eventId: -1,
+                    timestamp: timestamps[4],
+                    isPlayed: false,
+                },
+            ),
+            new OrchestratorStartedEvent(
+                {
+                    eventId: -1,
+                    timestamp: timestamps[5],
+                    isPlayed: false,
+                },
+            ),
+            new TaskCompletedEvent(
+                {
+                    eventId: -1,
+                    timestamp: timestamps[5],
+                    isPlayed: true,
+                    taskScheduledId: 3,
+                    result: JSON.stringify({ output: false }),
+                },
+            ),
+            new TaskScheduledEvent(
+                {
+                    eventId: 4,
+                    timestamp: timestamps[5],
+                    isPlayed: false,
+                    name: "CheckIfMerged",
+                },
+            ),
+            new OrchestratorCompletedEvent(
+                {
+                    eventId: -1,
+                    timestamp: timestamps[5],
+                    isPlayed: false,
+                },
+            ),
+            new OrchestratorStartedEvent(
+                {
+                    eventId: -1,
+                    timestamp: timestamps[6],
+                    isPlayed: false,
+                },
+            ),
+            new TaskCompletedEvent(
+                {
+                    eventId: -1,
+                    timestamp: timestamps[6],
+                    isPlayed: true,
+                    taskScheduledId: 4,
+                    result: JSON.stringify({ output: false }),
+                },
+            ),
+            new OrchestratorCompletedEvent(
+                {
+                    eventId: -1,
+                    timestamp: timestamps[6],
+                    isPlayed: false,
+                },
+            ),
+            new OrchestratorStartedEvent(
+                {
+                    eventId: -1,
+                    timestamp: timestamps[7],
+                    isPlayed: false,
+                },
+            ),
+            new EventRaisedEvent(
+                {
+                    eventId: -1,
+                    timestamp: timestamps[7],
+                    isPlayed: true,
+                    name: "CheckPrForMerge",
+                    input: JSON.stringify({ value: 2 }),
+                },
+            ),
+            new EventRaisedEvent(
+                {
+                    eventId: -1,
+                    timestamp: timestamps[7],
+                    isPlayed: true,
+                    name: "CheckPrForMerge",
+                    input: JSON.stringify({ value: 3 }),
+                },
+            ),
+            new EventRaisedEvent(
+                {
+                    eventId: -1,
+                    timestamp: timestamps[7],
+                    isPlayed: true,
+                    name: "CheckPrForMerge",
+                    input: JSON.stringify({ value: 4 }),
+                },
+            ),
+            new TaskScheduledEvent(
+                {
+                    eventId: 5,
+                    timestamp: timestamps[7],
+                    isPlayed: false,
+                    name: "CheckIfMerged",
+                },
+            ),
+            new OrchestratorCompletedEvent(
+                {
+                    eventId: -1,
+                    timestamp: timestamps[7],
+                    isPlayed: false,
+                },
+            ),
+            new OrchestratorStartedEvent(
+                {
+                    eventId: -1,
+                    timestamp: timestamps[8],
+                    isPlayed: false,
+                },
+            ),
+            new TaskCompletedEvent(
+                {
+                    eventId: -1,
+                    timestamp: timestamps[8],
+                    isPlayed: false,
+                    taskScheduledId: 5,
+                    result: JSON.stringify({ output: false }),
+                },
+            ),
+        ];
+    }
+
     public static GetSayHelloWithActivityReplayOne(
         name: string,
         firstTimestamp: Date,