Azure-functions-durable-extension: Duplicate activity calls and entity operations in v2.1.x

[olitomlinson]

2.1.1 :x:
2.1.0 :x:
2.0.0 :heavy_check_mark:
1.8.4 :heavy_check_mark:

VS2019 16.4
netcoreapp3.1
V3 Functions Runtime

---

Given that I raise the event chargeable-operation multiple times

I'm seeing the orchestration make multiple calls to the activity ChargeCustomer that it has already scheduled.

_Not to be confused_ with an activity loosing its lock and then getting reprocessed - I'm actually debugging through and seeing CallActivityAsync being called with the same count value with IsReplaying == False

I've tested this locally and in Consumption Plan many times with consistent results.

public async Task RunAsync([OrchestrationTrigger] DurableOrchestrationContext context)
{
    var count = context.GetInput<int?>() ?? 0;

    await context.WaitForExternalEvent("chargeable-operation");

    count += 1;

    var result = await context.CallActivityAsync<ChargeResult>(nameof(ChargeCustomer), count);

    context.ContinueAsNew(count);
    return;
}

public async Task<ChargeResult> ChargeCustomer([ActivityTrigger] DurableActivityContext context)
{
   var count = context.GetInput<int>();

   // 10 second wait to simulate work
   await Task.Delay(10000);

   _logger.SetSingleUseDimension("orchestrationId", context.InstanceId);
   _logger.SetSingleUseDimension("_count", count);
   _logger.TrackEvent("charge-customer");

    return new ChargeResult(count);
}

---

2.1.1 - count is duplicated :x:

2.1.0 - count is duplicated :x:

2.0.0 - count is unique :heavy_check_mark:

---

host.json

{
  "version": "2.0",
  "extensions": {
    "durableTask": {
      "hubName": "NewHub",
      "maxQueuePollingInterval": "00:00:10",
      "partitionCount": 1
    },
    "logging": {
      "logLevel": {
        "Host.Triggers.DurableTask": "Information",
        "Host.Results": "Information",
        "Function": "Information",
        "Host.Aggregator": "Information"
      }
    }
  }
}

[cgillum]

That's super interesting. Thank you for sharing this information. We'll need to look into what changed between these versions to cause this behavior.

[bragma]

I've tried to implement what I discussed here (solution 2).

@olitomlinson I have set up a sample repository which also calls an activity multiple times without reason (version 2.1.1). The problem is not present in version 2.0.0.
I am using an external event too, and the activity is called 3 times, just like in your case. It seems to be called 1 time (correctly) when the event is received, another time when the orchestration is waiting for the activity complete, and once again when the activity completes.

The repo is here:
https://github.com/bragma/DataOrTimer

The idea is to have an orchestration wait for a timer or an external event and restart after processing the event. A simple activity returns some data and a client triggers the orchestration (a singleton)
The problem is that the external event seems to trigger multiple time. Here is a log from the application level (with some comments):

=> Host is started:
[27/01/2020 09:07:02] [CLI] Starting new orchestration, expiring in 10 minutes

=> HTTP request sent to client, sends data to orchestration
[27/01/2020 09:07:02] [CLI] Sending data DATA:dc5bc423-228c-440e-ba1a-f2d839c498b7

=> Orchestration receives data, calls activity
[27/01/2020 09:07:03] [ORC] Orchestration begins with expiration at 27/01/2020 09:17:02, waitTime 00:00:30, next wakeup at 27/01/2020 09:07:32
[27/01/2020 09:07:03] [ORC] Data Event Triggered, data = DATA:dc5bc423-228c-440e-ba1a-f2d839c498b7

=> Activity starts and ends
[27/01/2020 09:07:03] [ACT] Saying hello to DATA:dc5bc423-228c-440e-ba1a-f2d839c498b7, STARTED.
[27/01/2020 09:07:13] [ACT] Saying hello to DATA:dc5bc423-228c-440e-ba1a-f2d839c498b7, DONE.

=> Orchestration receives data, logs result and restarts
[27/01/2020 09:07:14] [ORC] Activity result Hello DATA:dc5bc423-228c-440e-ba1a-f2d839c498b7!
[27/01/2020 09:07:14] [ORC] Restarting for another round

=> Orchestration waits, all OK
[27/01/2020 09:07:14] [ORC] Orchestration begins with expiration at 27/01/2020 09:17:02, waitTime 00:00:30, next wakeup at 27/01/2020 09:07:44

=> Here another HTTP request is sent to client, orchestration picks up the new data. Notice that the external events triggers the orchestration TWICE
[27/01/2020 09:07:22] [CLI] Orchestration already exists
[27/01/2020 09:07:22] [CLI] Sending data DATA:44b24533-4b5f-4ccb-960d-5da889a1ddac
[27/01/2020 09:07:22] [ORC] Data Event Triggered, data = DATA:44b24533-4b5f-4ccb-960d-5da889a1ddac
[27/01/2020 09:07:23] [ACT] Saying hello to DATA:44b24533-4b5f-4ccb-960d-5da889a1ddac, STARTED.

=> HERE THE ORCHESTRATION IS TRIGGERED AGAIN (while waiting for the activity to finish)
[27/01/2020 09:07:26] [ORC] Data Event Triggered, data = DATA:44b24533-4b5f-4ccb-960d-5da889a1ddac

=> Activity is called gain due to above
[27/01/2020 09:07:26] [ACT] Saying hello to DATA:44b24533-4b5f-4ccb-960d-5da889a1ddac, STARTED.
[27/01/2020 09:07:33] [ACT] Saying hello to DATA:44b24533-4b5f-4ccb-960d-5da889a1ddac, DONE.
[27/01/2020 09:07:36] [ACT] Saying hello to DATA:44b24533-4b5f-4ccb-960d-5da889a1ddac, DONE.

=> The 2 activities have finished, orchestration is resumed but the external event is triggered AGAIN.
[27/01/2020 09:07:46] [ORC] Data Event Triggered, data = DATA:44b24533-4b5f-4ccb-960d-5da889a1ddac

=> 3rd invocation of the activity
[27/01/2020 09:07:46] [ACT] Saying hello to DATA:44b24533-4b5f-4ccb-960d-5da889a1ddac, STARTED.
[27/01/2020 09:07:56] [ORC] Activity result Hello DATA:44b24533-4b5f-4ccb-960d-5da889a1ddac!
[27/01/2020 09:07:56] [ORC] Restarting for another round
[27/01/2020 09:07:56] [ORC] Orchestration begins with expiration at 27/01/2020 09:17:02, waitTime 00:00:30, next wakeup at 27/01/2020 09:08:26
[27/01/2020 09:07:57] [ACT] Saying hello to DATA:44b24533-4b5f-4ccb-960d-5da889a1ddac, DONE.
[27/01/2020 09:08:51] [ORC] Timer Triggered
[27/01/2020 09:08:51] [ORC] Restarting for another round
[27/01/2020 09:08:51] [ORC] Orchestration begins with expiration at 27/01/2020 09:17:02, waitTime 00:00:30, next wakeup at 27/01/2020 09:09:21

Full host log:

[27/01/2020 09:06:53] Task hub worker started. Latency: 00:00:01.5110661. InstanceId: . Function: . HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.1.1. SequenceNumber: 1.
[27/01/2020 09:06:53] Host started (1960ms)
[27/01/2020 09:06:53] Job host started
Hosting environment: Production
Content root path: C:\Devel\DataOrTimer\DataOrTimer\bin\Debug\netcoreapp2.1
Now listening on: http://0.0.0.0:7071
Application started. Press Ctrl+C to shut down.
[27/01/2020 09:06:58] Host lock lease acquired by instance ID '0000000000000000000000001E503A62'.
[27/01/2020 09:07:02] Executing HTTP request: {
[27/01/2020 09:07:02] "requestId": "deebddc8-a27e-4889-a1aa-5aa74be85193",
[27/01/2020 09:07:02] "method": "GET",
[27/01/2020 09:07:02] "uri": "/api/Function_HttpStart"
[27/01/2020 09:07:02] }
[27/01/2020 09:07:02] Executing 'Function_HttpStart' (Reason='This function was programmatically called via the host APIs.', Id=db564c1b-ea3a-4710-a290-7120608b9a2f)
[27/01/2020 09:07:02] >>>>>> [CLI] Starting new orchestration, expiring in 10 minutes
[27/01/2020 09:07:02] SingletonId: Function 'RunOrchestrator (Orchestrator)' scheduled. Reason: NewInstance. IsReplay: False. State: Scheduled. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.1.1. SequenceNumber: 2.
[27/01/2020 09:07:02] >>>>>> [CLI] Sending data DATA:dc5bc423-228c-440e-ba1a-f2d839c498b7
[27/01/2020 09:07:02] SingletonId: Function 'RunOrchestrator (Orchestrator)' scheduled. Reason: RaiseEvent:NewData. IsReplay: False. State: Scheduled. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.1.1. SequenceNumber: 3.
[27/01/2020 09:07:02] Executed 'Function_HttpStart' (Succeeded, Id=db564c1b-ea3a-4710-a290-7120608b9a2f)
[27/01/2020 09:07:03] Executing 'RunOrchestrator' (Reason='', Id=6a70b3e9-7454-479f-92c0-de08893fe9c4)
[27/01/2020 09:07:03] SingletonId: Function 'RunOrchestrator (Orchestrator)' started. IsReplay: False. Input: (120 bytes). State: Started. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.1.1. SequenceNumber: 4.
[27/01/2020 09:07:03] >>>>>> [ORC] Orchestration begins with expiration at 27/01/2020 09:17:02, waitTime 00:00:30, next wakeup at 27/01/2020 09:07:32
[27/01/2020 09:07:03] SingletonId: Function 'RunOrchestrator (Orchestrator)' is waiting for input. Reason: CreateTimer:2020-01-27T09:07:32.8826921Z. IsReplay: False. State: Listening. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.1.1. SequenceNumber: 5.
[27/01/2020 09:07:03] Executed HTTP request: {
[27/01/2020 09:07:03] "requestId": "deebddc8-a27e-4889-a1aa-5aa74be85193",
[27/01/2020 09:07:03] SingletonId: Function 'RunOrchestrator (Orchestrator)' is waiting for input. Reason: WaitForExternalEvent:NewData. IsReplay: False. State: Listening. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.1.1. SequenceNumber: 6.
[27/01/2020 09:07:03] "method": "GET",
[27/01/2020 09:07:03] Executed 'RunOrchestrator' (Succeeded, Id=6a70b3e9-7454-479f-92c0-de08893fe9c4)
[27/01/2020 09:07:03] "uri": "/api/Function_HttpStart",
[27/01/2020 09:07:03] "identities": [
[27/01/2020 09:07:03] SingletonId: Function 'RunOrchestrator (Orchestrator)' awaited. IsReplay: False. State: Awaited. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.1.1. SequenceNumber: 7.
[27/01/2020 09:07:03] {
[27/01/2020 09:07:03] "type": "WebJobsAuthLevel",
[27/01/2020 09:07:03] "level": "Admin"
[27/01/2020 09:07:03] }
[27/01/2020 09:07:03] ],
[27/01/2020 09:07:03] "status": 202,
[27/01/2020 09:07:03] "duration": 927
[27/01/2020 09:07:03] }
[27/01/2020 09:07:03] Executing 'RunOrchestrator' (Reason='', Id=4f1eb94c-8ba0-4361-9daa-cba909afbf52)
[27/01/2020 09:07:03] SingletonId: Function 'RunOrchestrator (Orchestrator)' received a 'NewData' event. State: ExternalEventRaised. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.1.1. SequenceNumber: 8.
[27/01/2020 09:07:03] >>>>>> [ORC] Data Event Triggered, data = DATA:dc5bc423-228c-440e-ba1a-f2d839c498b7
[27/01/2020 09:07:03] SingletonId: Function 'SayHello (Activity)' scheduled. Reason: RunOrchestrator. IsReplay: False. State: Scheduled. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.1.1. SequenceNumber: 9.
[27/01/2020 09:07:03] Executed 'RunOrchestrator' (Succeeded, Id=4f1eb94c-8ba0-4361-9daa-cba909afbf52)
[27/01/2020 09:07:03] SingletonId: Function 'RunOrchestrator (Orchestrator)' awaited. IsReplay: False. State: Awaited. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.1.1. SequenceNumber: 10.
[27/01/2020 09:07:03] SingletonId: Function 'SayHello (Activity)' started. IsReplay: False. Input: (180 bytes). State: Started. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.1.1. SequenceNumber: 11.
[27/01/2020 09:07:03] Executing 'SayHello' (Reason='', Id=c6d45bb1-083c-4d5b-94ca-d7accc6f6cf6)
[27/01/2020 09:07:03] >>>>>> [ACT] Saying hello to DATA:dc5bc423-228c-440e-ba1a-f2d839c498b7, STARTED.
[27/01/2020 09:07:13] >>>>>> [ACT] Saying hello to DATA:dc5bc423-228c-440e-ba1a-f2d839c498b7, DONE.
[27/01/2020 09:07:13] Executed 'SayHello' (Succeeded, Id=c6d45bb1-083c-4d5b-94ca-d7accc6f6cf6)
[27/01/2020 09:07:13] SingletonId: Function 'SayHello (Activity)' completed. ContinuedAsNew: False. IsReplay: False. Output: (200 bytes). State: Completed. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.1.1. SequenceNumber: 12.
[27/01/2020 09:07:14] Executing 'RunOrchestrator' (Reason='', Id=8201f057-ef4b-47e5-89a0-c161de9a29aa)
[27/01/2020 09:07:14] SingletonId: Function 'RunOrchestrator (Orchestrator)' received a 'NewData' event. State: ExternalEventRaised. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.1.1. SequenceNumber: 13.
[27/01/2020 09:07:14] >>>>>> [ORC] Activity result Hello DATA:dc5bc423-228c-440e-ba1a-f2d839c498b7!
[27/01/2020 09:07:14] >>>>>> [ORC] Restarting for another round
[27/01/2020 09:07:14] SingletonId: Function 'RunOrchestrator (Orchestrator)' completed. ContinuedAsNew: True. IsReplay: False. Output: (null). State: Completed. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.1.1. SequenceNumber: 14.
[27/01/2020 09:07:14] Executed 'RunOrchestrator' (Succeeded, Id=8201f057-ef4b-47e5-89a0-c161de9a29aa)
[27/01/2020 09:07:14] Executing 'RunOrchestrator' (Reason='', Id=097f81a4-6c98-4f40-bb18-bac2275e9308)
[27/01/2020 09:07:14] SingletonId: Function 'RunOrchestrator (Orchestrator)' started. IsReplay: False. Input: (120 bytes). State: Started. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.1.1. SequenceNumber: 15.
[27/01/2020 09:07:14] >>>>>> [ORC] Orchestration begins with expiration at 27/01/2020 09:17:02, waitTime 00:00:30, next wakeup at 27/01/2020 09:07:44
[27/01/2020 09:07:14] SingletonId: Function 'RunOrchestrator (Orchestrator)' is waiting for input. Reason: CreateTimer:2020-01-27T09:07:44.1739113Z. IsReplay: False. State: Listening. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.1.1. SequenceNumber: 16.
[27/01/2020 09:07:14] SingletonId: Function 'RunOrchestrator (Orchestrator)' is waiting for input. Reason: WaitForExternalEvent:NewData. IsReplay: False. State: Listening. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.1.1. SequenceNumber: 17.
[27/01/2020 09:07:14] Executed 'RunOrchestrator' (Succeeded, Id=097f81a4-6c98-4f40-bb18-bac2275e9308)
[27/01/2020 09:07:14] SingletonId: Function 'RunOrchestrator (Orchestrator)' awaited. IsReplay: False. State: Awaited. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.1.1. SequenceNumber: 18.
[27/01/2020 09:07:22] Executing HTTP request: {
[27/01/2020 09:07:22] "requestId": "7b24640b-0ade-43d0-88c6-a5b404e499fb",
[27/01/2020 09:07:22] "method": "GET",
[27/01/2020 09:07:22] "uri": "/api/Function_HttpStart"
[27/01/2020 09:07:22] }
[27/01/2020 09:07:22] Executing 'Function_HttpStart' (Reason='This function was programmatically called via the host APIs.', Id=58ccaeb8-82ca-422c-a0fc-3908cd54b6a3)
[27/01/2020 09:07:22] >>>>>> [CLI] Orchestration already exists
[27/01/2020 09:07:22] >>>>>> [CLI] Sending data DATA:44b24533-4b5f-4ccb-960d-5da889a1ddac
[27/01/2020 09:07:22] SingletonId: Function 'RunOrchestrator (Orchestrator)' scheduled. Reason: RaiseEvent:NewData. IsReplay: False. State: Scheduled. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.1.1. SequenceNumber: 19.
[27/01/2020 09:07:22] Executed 'Function_HttpStart' (Succeeded, Id=58ccaeb8-82ca-422c-a0fc-3908cd54b6a3)
[27/01/2020 09:07:22] Executing 'RunOrchestrator' (Reason='', Id=440d4664-e1e6-44d3-8016-db1087252202)
[27/01/2020 09:07:22] Executed HTTP request: {
[27/01/2020 09:07:22] SingletonId: Function 'RunOrchestrator (Orchestrator)' received a 'NewData' event. State: ExternalEventRaised. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.1.1. SequenceNumber: 20.
[27/01/2020 09:07:22] "requestId": "7b24640b-0ade-43d0-88c6-a5b404e499fb",
[27/01/2020 09:07:22] "method": "GET",
[27/01/2020 09:07:22] "uri": "/api/Function_HttpStart",
[27/01/2020 09:07:22] >>>>>> [ORC] Data Event Triggered, data = DATA:44b24533-4b5f-4ccb-960d-5da889a1ddac
[27/01/2020 09:07:23] "identities": [
[27/01/2020 09:07:23] {
[27/01/2020 09:07:23] "type": "WebJobsAuthLevel",
[27/01/2020 09:07:23] "level": "Admin"[27/01/2020 09:07:23] SingletonId: Function 'SayHello (Activity)' scheduled. Reason: RunOrchestrator. IsReplay: False. State: Scheduled. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.1.1. SequenceNumber: 21.

[27/01/2020 09:07:23] }
[27/01/2020 09:07:23] Executed 'RunOrchestrator' (Succeeded, Id=440d4664-e1e6-44d3-8016-db1087252202)
[27/01/2020 09:07:23] ],
[27/01/2020 09:07:23] "status": 202,
[27/01/2020 09:07:23] SingletonId: Function 'RunOrchestrator (Orchestrator)' awaited. IsReplay: False. State: Awaited. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.1.1. SequenceNumber: 22.
[27/01/2020 09:07:23] "duration": 159
[27/01/2020 09:07:23] }
[27/01/2020 09:07:23] SingletonId: Function 'SayHello (Activity)' started. IsReplay: False. Input: (180 bytes). State: Started. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.1.1. SequenceNumber: 23.
[27/01/2020 09:07:23] Executing 'SayHello' (Reason='', Id=12de3f7d-484f-4cec-b373-345659ab56d3)
[27/01/2020 09:07:23] >>>>>> [ACT] Saying hello to DATA:44b24533-4b5f-4ccb-960d-5da889a1ddac, STARTED.
[27/01/2020 09:07:26] Executing 'RunOrchestrator' (Reason='', Id=a50a9ccd-98d2-43d4-9940-4802691e513f)
[27/01/2020 09:07:26] SingletonId: Function 'RunOrchestrator (Orchestrator)' received a 'NewData' event. State: ExternalEventRaised. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.1.1. SequenceNumber: 24.
[27/01/2020 09:07:26] >>>>>> [ORC] Data Event Triggered, data = DATA:44b24533-4b5f-4ccb-960d-5da889a1ddac
[27/01/2020 09:07:26] SingletonId: Function 'SayHello (Activity)' scheduled. Reason: RunOrchestrator. IsReplay: False. State: Scheduled. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.1.1. SequenceNumber: 25.
[27/01/2020 09:07:26] Executed 'RunOrchestrator' (Succeeded, Id=a50a9ccd-98d2-43d4-9940-4802691e513f)
[27/01/2020 09:07:26] SingletonId: Function 'RunOrchestrator (Orchestrator)' awaited. IsReplay: False. State: Awaited. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.1.1. SequenceNumber: 26.
[27/01/2020 09:07:26] SingletonId: Function 'SayHello (Activity)' started. IsReplay: False. Input: (180 bytes). State: Started. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.1.1. SequenceNumber: 27.
[27/01/2020 09:07:26] Executing 'SayHello' (Reason='', Id=ed4cc4e6-fd36-4ba9-803c-336c39fe9f5c)
[27/01/2020 09:07:26] >>>>>> [ACT] Saying hello to DATA:44b24533-4b5f-4ccb-960d-5da889a1ddac, STARTED.
[27/01/2020 09:07:33] >>>>>> [ACT] Saying hello to DATA:44b24533-4b5f-4ccb-960d-5da889a1ddac, DONE.
[27/01/2020 09:07:33] Executed 'SayHello' (Succeeded, Id=12de3f7d-484f-4cec-b373-345659ab56d3)
[27/01/2020 09:07:33] SingletonId: Function 'SayHello (Activity)' completed. ContinuedAsNew: False. IsReplay: False. Output: (200 bytes). State: Completed. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.1.1. SequenceNumber: 28.
[27/01/2020 09:07:36] >>>>>> [ACT] Saying hello to DATA:44b24533-4b5f-4ccb-960d-5da889a1ddac, DONE.
[27/01/2020 09:07:36] Executed 'SayHello' (Succeeded, Id=ed4cc4e6-fd36-4ba9-803c-336c39fe9f5c)
[27/01/2020 09:07:36] SingletonId: Function 'SayHello (Activity)' completed. ContinuedAsNew: False. IsReplay: False. Output: (200 bytes). State: Completed. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.1.1. SequenceNumber: 29.
[27/01/2020 09:07:46] Executing 'RunOrchestrator' (Reason='', Id=1aafad3a-d5fa-42e1-a18c-29c853763d8c)
[27/01/2020 09:07:46] SingletonId: Function 'RunOrchestrator (Orchestrator)' received a 'NewData' event. State: ExternalEventRaised. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.1.1. SequenceNumber: 30.
[27/01/2020 09:07:46] >>>>>> [ORC] Data Event Triggered, data = DATA:44b24533-4b5f-4ccb-960d-5da889a1ddac
[27/01/2020 09:07:46] SingletonId: Function 'SayHello (Activity)' scheduled. Reason: RunOrchestrator. IsReplay: False. State: Scheduled. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.1.1. SequenceNumber: 31.
[27/01/2020 09:07:46] Executed 'RunOrchestrator' (Succeeded, Id=1aafad3a-d5fa-42e1-a18c-29c853763d8c)
[27/01/2020 09:07:46] SingletonId: Function 'RunOrchestrator (Orchestrator)' awaited. IsReplay: False. State: Awaited. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.1.1. SequenceNumber: 32.
[27/01/2020 09:07:46] SingletonId: Function 'SayHello (Activity)' started. IsReplay: False. Input: (180 bytes). State: Started. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.1.1. SequenceNumber: 33.
[27/01/2020 09:07:46] Executing 'SayHello' (Reason='', Id=eaf8373b-eaeb-4c66-a59d-fb1397807eb9)
[27/01/2020 09:07:46] >>>>>> [ACT] Saying hello to DATA:44b24533-4b5f-4ccb-960d-5da889a1ddac, STARTED.
[27/01/2020 09:07:56] Executing 'RunOrchestrator' (Reason='', Id=4bcc558c-b49e-42a4-adc6-aeff0b627b89)
[27/01/2020 09:07:56] SingletonId: Function 'RunOrchestrator (Orchestrator)' received a 'NewData' event. State: ExternalEventRaised. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.1.1. SequenceNumber: 34.
[27/01/2020 09:07:56] >>>>>> [ORC] Activity result Hello DATA:44b24533-4b5f-4ccb-960d-5da889a1ddac!
[27/01/2020 09:07:56] >>>>>> [ORC] Restarting for another round
[27/01/2020 09:07:56] SingletonId: Function 'RunOrchestrator (Orchestrator)' completed. ContinuedAsNew: True. IsReplay: False. Output: (null). State: Completed. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.1.1. SequenceNumber: 35.
[27/01/2020 09:07:56] Executed 'RunOrchestrator' (Succeeded, Id=4bcc558c-b49e-42a4-adc6-aeff0b627b89)
[27/01/2020 09:07:56] Executing 'RunOrchestrator' (Reason='', Id=64e9c1a8-7319-4c5e-93c6-2733514f078c)
[27/01/2020 09:07:56] SingletonId: Function 'RunOrchestrator (Orchestrator)' started. IsReplay: False. Input: (120 bytes). State: Started. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.1.1. SequenceNumber: 36.
[27/01/2020 09:07:56] >>>>>> [ORC] Orchestration begins with expiration at 27/01/2020 09:17:02, waitTime 00:00:30, next wakeup at 27/01/2020 09:08:26
[27/01/2020 09:07:56] SingletonId: Function 'RunOrchestrator (Orchestrator)' is waiting for input. Reason: CreateTimer:2020-01-27T09:08:26.8653618Z. IsReplay: False. State: Listening. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.1.1. SequenceNumber: 37.
[27/01/2020 09:07:56] SingletonId: Function 'RunOrchestrator (Orchestrator)' is waiting for input. Reason: WaitForExternalEvent:NewData. IsReplay: False. State: Listening. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.1.1. SequenceNumber: 38.
[27/01/2020 09:07:56] Executed 'RunOrchestrator' (Succeeded, Id=64e9c1a8-7319-4c5e-93c6-2733514f078c)
[27/01/2020 09:07:56] SingletonId: Function 'RunOrchestrator (Orchestrator)' awaited. IsReplay: False. State: Awaited. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.1.1. SequenceNumber: 39.
[27/01/2020 09:07:57] >>>>>> [ACT] Saying hello to DATA:44b24533-4b5f-4ccb-960d-5da889a1ddac, DONE.
[27/01/2020 09:07:57] Executed 'SayHello' (Succeeded, Id=eaf8373b-eaeb-4c66-a59d-fb1397807eb9)
[27/01/2020 09:07:57] SingletonId: Function 'SayHello (Activity)' completed. ContinuedAsNew: False. IsReplay: False. Output: (200 bytes). State: Completed. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.1.1. SequenceNumber: 40.
[27/01/2020 09:08:51] Executing 'RunOrchestrator' (Reason='', Id=b5f761f7-32a0-456e-868e-c8faa172250d)
[27/01/2020 09:08:51] SingletonId: Function 'RunOrchestrator (Orchestrator)' was resumed by a timer scheduled for '2020-01-27T09:08:26.8653618Z'. IsReplay: False. State: TimerExpired. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.1.1. SequenceNumber: 41.
[27/01/2020 09:08:51] >>>>>> [ORC] Timer Triggered
[27/01/2020 09:08:51] >>>>>> [ORC] Restarting for another round
[27/01/2020 09:08:51] SingletonId: Function 'RunOrchestrator (Orchestrator)' completed. ContinuedAsNew: True. IsReplay: False. Output: (null). State: Completed. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.1.1. SequenceNumber: 42.
[27/01/2020 09:08:51] Executed 'RunOrchestrator' (Succeeded, Id=b5f761f7-32a0-456e-868e-c8faa172250d)
[27/01/2020 09:08:51] Executing 'RunOrchestrator' (Reason='', Id=c7713c6a-1918-4ae6-b083-8274c253d6d0)
[27/01/2020 09:08:51] SingletonId: Function 'RunOrchestrator (Orchestrator)' started. IsReplay: False. Input: (120 bytes). State: Started. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.1.1. SequenceNumber: 43.
[27/01/2020 09:08:51] >>>>>> [ORC] Orchestration begins with expiration at 27/01/2020 09:17:02, waitTime 00:00:30, next wakeup at 27/01/2020 09:09:21
[27/01/2020 09:08:51] SingletonId: Function 'RunOrchestrator (Orchestrator)' is waiting for input. Reason: CreateTimer:2020-01-27T09:09:21.9651327Z. IsReplay: False. State: Listening. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.1.1. SequenceNumber: 44.
[27/01/2020 09:08:51] SingletonId: Function 'RunOrchestrator (Orchestrator)' is waiting for input. Reason: WaitForExternalEvent:NewData. IsReplay: False. State: Listening. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.1.1. SequenceNumber: 45.
[27/01/2020 09:08:51] Executed 'RunOrchestrator' (Succeeded, Id=c7713c6a-1918-4ae6-b083-8274c253d6d0)
[27/01/2020 09:08:51] SingletonId: Function 'RunOrchestrator (Orchestrator)' awaited. IsReplay: False. State: Awaited. HubName: TestHubName. AppName: . SlotName: . ExtensionVersion: 2.1.1. SequenceNumber: 46.

[olitomlinson]

Yep, I would say there is a strong possibility we are looking at the same bug here. 👍🏻

@cgillum It appears to be introduced in 2.1.0. This feels like a high priority bug given that it forces multiple executions of an Activity. I imagine that despite guidance, many activities out in the wild are not idempotent.

[bragma]

@olitomlinson even if idempotent, nobody likes running DB queries without reason :D

I agree for the high priority because if the cause is repeated external events, it may be even more serious than repeating activities (ex: update a counter in durable entity on event).

[olitomlinson]

@bragma That is very true! :)

[ConnorMcMahon]

@olitomlinson,

I think I have found the root cause, though I would like to do a bit more investigation into why we always succeed after 3 activity executions.

I hopefully will have a fix ready in the next couple of days, and they will make it into our next release of DurableTask.AzureStorage.

[olitomlinson]

@ConnorMcMahon awesome! So glad I can help! Let me know if you need a pre-release testing ☺️

[ConnorMcMahon]

Fix is here. I need to test it end-to-end with my repro, but I am 95% sure it will resolve the issue.

[bragma]

Fix is here. I need to test it end-to-end with my repro, but I am 95% sure it will resolve the issue.

I think I could test it with my sample project but I am not sure how to get the fix... Do I have to build this manually or is there a package to install?

[ConnorMcMahon]

@bragma

I will get a nupkg on our myget feed sometime today so you can start testing it.

[ConnorMcMahon]

@bragma and @olitomlinson

I have uploaded a package to the azure-appservice-staging feed. Add it as a package source, and the following package reference:

<PackageReference Include="Microsoft.Azure.DurableTask.AzureStorage" Version="1.7.2-preview" />

[bragma]

@ConnorMcMahon I've tested the preview package. Problem is fixed, great job!

[ConnorMcMahon]

@bragma and @olitomlinson, the fix is officially on nuget. Just reference DurableTask.AzureStorage explicitly like below:

<PackageReference Include="Microsoft.Azure.DurableTask.AzureStorage" Version="1.7.2" />

This will be the default version of DurableTask.AzureStorage used in v1.8.5 and 2.2.0 of the extension.

[ConnorMcMahon]

Fixed in 2.2.0