0

The below question stems from my work trying to use the fan out/fan in pattern to gather license data for 130k users to input to our database for reporting and license management. I have this piece functioning correctly in a different project but it is exceeding the timeout of a standard Azure function. I ported it to the durable function and ran into this issue, then backtracked to the pre-generated code in an attempt to find the issue but it exists no matter what I do.

The below is in a fresh project using the pre-generated code for the Durable Functions. No changes to the code made at all.

When I run the code, it calls the same function multiple times with the same timestamp and different ID's. It then continuously calls Function1_Hello.

I have done some research to try and determine what is causing this but have not been able to find an answer or resolution. Similar question here and some deep research done here but I have not seen an actual resolution to this issue. Any help is greatly appreciated.

Code

using System.Collections.Generic;
using System.Net.Http;
using System.Threading.Tasks;
using Microsoft.Azure.WebJobs;
using Microsoft.Azure.WebJobs.Extensions.DurableTask;
using Microsoft.Azure.WebJobs.Extensions.Http;
using Microsoft.Azure.WebJobs.Host;
using Microsoft.Extensions.Logging;

namespace DurableFunctionTest
{
    public static class Function1
    {
        [FunctionName("Function1")]
        public static async Task<List<string>> RunOrchestrator(
            [OrchestrationTrigger] IDurableOrchestrationContext context)
        {
            var outputs = new List<string>();

            // Replace "hello" with the name of your Durable Activity Function.
            outputs.Add(await context.CallActivityAsync<string>("Function1_Hello", "Tokyo"));
            outputs.Add(await context.CallActivityAsync<string>("Function1_Hello", "Seattle"));
            outputs.Add(await context.CallActivityAsync<string>("Function1_Hello", "London"));

            // returns ["Hello Tokyo!", "Hello Seattle!", "Hello London!"]
            return outputs;
        }

        [FunctionName("Function1_Hello")]
        public static string SayHello([ActivityTrigger] string name, ILogger log)
        {
            log.LogInformation($"Saying hello to {name}.");
            return $"Hello {name}!";
        }

        [FunctionName("Function1_HttpStart")]
        public static async Task<HttpResponseMessage> HttpStart(
            [HttpTrigger(AuthorizationLevel.Anonymous, "get", "post")] HttpRequestMessage req,
            [DurableClient] IDurableOrchestrationClient starter,
            ILogger log)
        {
            // Function input comes from the request content.
            string instanceId = await starter.StartNewAsync("Function1", null);

            log.LogInformation($"Started orchestration with ID = '{instanceId}'.");

            return starter.CreateCheckStatusResponse(req, instanceId);
        }
    }
}

Console results from running the code here.

For detailed output, run func with --verbose flag.
[2022-09-28T16:54:28.492Z] Executing 'Function1_Hello' (Reason='(null)', Id=76fc4193-219e-4347-ab08-880785a2d73e)
[2022-09-28T16:54:28.492Z] Executing 'Function1_Hello' (Reason='(null)', Id=022d09eb-0960-427a-8777-c99062c50e34)[2022-09-28T16:54:28.492Z] Executing 'Function1_Hello' (Reason='(null)', Id=69633782-4904-4ee8-b88a-228e96a4b8de)

[2022-09-28T16:54:28.492Z] Executing 'Function1_Hello' (Reason='(null)', Id=374d38c5-b2b7-4729-9dc0-7ea3e508a564)
[2022-09-28T16:54:28.492Z] Executing 'Function1_Hello' (Reason='(null)', Id=48cd6a04-ee9d-4f30-aff8-59af54233bb6)
[2022-09-28T16:54:29.435Z] Saying hello to Tokyo.
[2022-09-28T16:54:29.456Z] Saying hello to Tokyo.
[2022-09-28T16:54:29.620Z] Saying hello to Tokyo.
[2022-09-28T16:54:29.761Z] Saying hello to Tokyo.
[2022-09-28T16:54:29.761Z] Saying hello to Tokyo.
[2022-09-28T16:54:29.781Z] Host lock lease acquired by instance ID '00000000000000000000000042B5BCB0'.
[2022-09-28T16:54:29.862Z] Executed 'Function1_Hello' (Succeeded, Id=69633782-4904-4ee8-b88a-228e96a4b8de, Duration=2281ms)
[2022-09-28T16:54:29.862Z] Executed 'Function1_Hello' (Succeeded, Id=76fc4193-219e-4347-ab08-880785a2d73e, Duration=2438ms)
[2022-09-28T16:54:29.862Z] Executed 'Function1_Hello' (Succeeded, Id=374d38c5-b2b7-4729-9dc0-7ea3e508a564, Duration=2417ms)
[2022-09-28T16:54:29.862Z] Executed 'Function1_Hello' (Succeeded, Id=48cd6a04-ee9d-4f30-aff8-59af54233bb6, Duration=2437ms)
[2022-09-28T16:54:29.862Z] Executed 'Function1_Hello' (Succeeded, Id=022d09eb-0960-427a-8777-c99062c50e34, Duration=2297ms)
[2022-09-28T16:54:59.644Z] Executing 'Function1' (Reason='(null)', Id=0eaa8de6-d050-4d50-91f9-96c2f019cfeb)
[2022-09-28T16:54:59.644Z] Executing 'Function1' (Reason='(null)', Id=56461ac1-0b65-4797-8d93-38e3b6184db9)[2022-09-28T16:54:59.644Z] Executing 'Function1' (Reason='(null)', Id=64540679-8f5a-4507-a656-8a011874fe9a)

[2022-09-28T16:54:59.644Z] Executing 'Function1' (Reason='(null)', Id=641d8c52-cce8-4076-a384-b05adc05ab89)
[2022-09-28T16:55:00.672Z] Executing 'Function1' (Reason='(null)', Id=7ab59722-55b1-4fbd-a3e6-c957e3da99f9)
[2022-09-28T16:55:00.743Z] Executed 'Function1' (Succeeded, Id=0eaa8de6-d050-4d50-91f9-96c2f019cfeb, Duration=1572ms)
[2022-09-28T16:55:00.743Z] Executed 'Function1' (Succeeded, Id=64540679-8f5a-4507-a656-8a011874fe9a, Duration=1572ms)
[2022-09-28T16:55:00.795Z] Executed 'Function1' (Succeeded, Id=7ab59722-55b1-4fbd-a3e6-c957e3da99f9, Duration=125ms)
[2022-09-28T16:55:00.795Z] Executed 'Function1' (Succeeded, Id=641d8c52-cce8-4076-a384-b05adc05ab89, Duration=1625ms)
[2022-09-28T16:55:00.795Z] Executed 'Function1' (Succeeded, Id=56461ac1-0b65-4797-8d93-38e3b6184db9, Duration=1624ms)
[2022-09-28T16:55:01.291Z] Executing 'Function1_Hello' (Reason='(null)', Id=069b5928-0947-4c33-842e-befd8d38c9d4)
[2022-09-28T16:55:01.340Z] Saying hello to Seattle.
[2022-09-28T16:55:01.367Z] Executing 'Function1_Hello' (Reason='(null)', Id=346e37d5-fb8d-4ab9-9340-272eee8219a0)
[2022-09-28T16:55:01.413Z] Executed 'Function1_Hello' (Succeeded, Id=069b5928-0947-4c33-842e-befd8d38c9d4, Duration=75ms)[2022-09-28T16:55:01.417Z] Saying hello to Seattle.

[2022-09-28T16:55:01.442Z] Executed 'Function1_Hello' (Succeeded, Id=346e37d5-fb8d-4ab9-9340-272eee8219a0, Duration=76ms)
[2022-09-28T16:55:01.442Z] Executing 'Function1_Hello' (Reason='(null)', Id=68f9d521-3178-40a3-9b7b-e8dea8c29f19)
[2022-09-28T16:55:01.617Z] Saying hello to Tokyo.
[2022-09-28T16:55:01.619Z] Executing 'Function1_Hello' (Reason='(null)', Id=8dac2a24-0796-40b1-9fc5-97fc14fc7d7c)
[2022-09-28T16:55:01.729Z] Executed 'Function1_Hello' (Succeeded, Id=68f9d521-3178-40a3-9b7b-e8dea8c29f19, Duration=268ms)
[2022-09-28T16:55:01.783Z] Saying hello to Tokyo.
[2022-09-28T16:55:01.787Z] Executing 'Function1_Hello' (Reason='(null)', Id=94bc6a3c-9aba-4857-bc17-01092dacc8ce)
[2022-09-28T16:55:01.944Z] Executed 'Function1_Hello' (Succeeded, Id=8dac2a24-0796-40b1-9fc5-97fc14fc7d7c, Duration=326ms)
[2022-09-28T16:55:02.026Z] Saying hello to Tokyo.
[2022-09-28T16:55:02.053Z] Executed 'Function1_Hello' (Succeeded, Id=94bc6a3c-9aba-4857-bc17-01092dacc8ce, Duration=266ms)
[2022-09-28T16:55:06.515Z] Executing 'Function1' (Reason='(null)', Id=8de1ae6e-b19d-49b0-9559-3817218f81de)
[2022-09-28T16:55:06.515Z] Executing 'Function1' (Reason='(null)', Id=1707f89b-dc2d-466d-ace2-68dadfebf991)
[2022-09-28T16:55:06.535Z] Executed 'Function1' (Succeeded, Id=8de1ae6e-b19d-49b0-9559-3817218f81de, Duration=20ms)
[2022-09-28T16:55:06.547Z] Executed 'Function1' (Succeeded, Id=1707f89b-dc2d-466d-ace2-68dadfebf991, Duration=32ms)
[2022-09-28T16:55:06.909Z] Executing 'Function1_Hello' 
(Reason='(null)', Id=239bdb01-e2cb-42de-84a3-22ec9ce582c8)
Litmas
  • 76
  • 1
  • 1
  • 8
  • 1
    Hmm, that is really odd that it is running the activities again like that.. Have you tried to use an empty task hub? (new queues/tables etc.) You can test that by changing the task hub name in host.json: https://learn.microsoft.com/en-us/azure/azure-functions/durable/durable-functions-bindings?tabs=csharp%2C2x-durable-functions#host-json (it's the "hubName" setting) – juunas Sep 28 '22 at 17:12
  • One possible reason would be that there were still messages in the work item queue waiting to execute the activities from previous tests and those ran when you started the app. – juunas Sep 28 '22 at 17:13
  • @juunas Thanks for putting me on the right track. Did some additional research on the task hubs and it looks like you are correct. Each previous time I debugged the program was storing Tasks in the Task Hub and then gathering and restarting them when debugging the program again. Details at [Task Hubs](https://learn.microsoft.com/en-us/azure/azure-functions/durable/durable-functions-task-hubs?tabs=csharp). Now to add instance management to my program! – Litmas Sep 29 '22 at 13:17

1 Answers1

0

Based on the discussion in the comments, it seems that activity start messages had been sent in previous runs to the work item queue, and when the Function was restarted, those activities executed.

A really easy way to ensure previous data is not used is to change the task hub name. You can specify one in the host.json:

{
  "extensions": {
    "durableTask": {
      "hubName": "MyHubName"
    }
  }
}

Note however that if you commit this change to Azure, it'll also clear the state there.

Alternatively, you can delete the queues and tables created for your local testing and Durable Functions will recreate them on startup.

juunas
  • 54,244
  • 13
  • 113
  • 149