Azure Durable function. orchestration spawns many unwanted activities

Question

I am trying to do some data transformation with durable functions. For that I have a TimerTriggered function which calls an Orchestration function that then spawns the transformation activities.

My problem is that immediately as the Orchestration function is called it then spawns a lot of activities before even getting to the part of the code which starts the function. My orchestration function is only supposed to start 3 activities as my dataList only contains 3 elements.

But as can be seen, in the log output I have included below, then a lot of activity functions will immediately run after the orchestration function has been called, before the loop containing context.CallActivityAsync begins

I can not find any cause for this at all. After these many activities have been started then my loop will actually run and start the 3 activities I expect.

TimerTriggered Function:

[FunctionName("StartupFunc")]
public static async Task Run([TimerTrigger("0 */5 * * * *", RunOnStartup = true, UseMonitor = false)]TimerInfo myStartTimer, [OrchestrationClient] DurableOrchestrationClient orchestrationClient, TraceWriter log)
{
    log.Info("*** STARTUP FUNCTION *** - Time triggered");
    List<OrchestrationModel> ExportModels = await getData();

    log.Info("** Orchestration Start **");
    string id = await orchestrationClient.StartNewAsync("OrchestratorFunc", ExportModels);
    log.Info("** Orchestration End **");
}

Orchestration Function:

[FunctionName("OrchestratorFunc")]
public static async Task<string> TransformOrchestration([OrchestrationTrigger] DurableOrchestrationContext context, TraceWriter log)
{
    var dataList = context.GetInput<List<OrchestrationModel>>();

    foreach (var data in dataList)
    {
        await context.CallActivityAsync<string>("TransformToFormat", new TransformModel(data));
    }
}

Activity function:

[FunctionName("TransformToFormat")]
[public static async Task<string> RunTransformation([ActivityTrigger] DurableActivityContext context, TraceWriter log)
{
    log.Info($"*** TRANSFORM FUNCTION - ACTIVITY *** executed at: {DateTime.Now}  ({context.InstanceId})");
    TransformModel = context.GetInput<TransformModel>();

    //Do some work with TransformModel
    log.Info($"* 1 ({context.InstanceId})");
    //Do more work
    log.Info($"* 4 ({context.InstanceId})");
    return $"return value ({context.InstanceId})");
}

Log output:

[21/9/2018 03:09:02] Reading host configuration file 'D:\git\TopoAPI\SyncToSQL\bin\Debug\net461\host.json'
[21/9/2018 03:09:02] Host configuration file read:
[21/9/2018 03:09:02] {}
[21/9/2018 03:09:02] Starting Host (HostId=topored-988367233, Version=1.0.11913.0, InstanceId=fe4247ff-d15f-4587-8efe-4c3e53fd776d, ProcessId=22320, AppDomainId=1, Debug=False, ConsecutiveErrors=0, StartupCount=1, FunctionsExtensionVersion=)
[21/9/2018 03:09:02] Loaded custom extension 'BotFrameworkConfiguration'
[21/9/2018 03:09:02] Loaded custom extension 'SendGridConfiguration'
[21/9/2018 03:09:02] Loaded custom extension 'EventGridExtensionConfig'
[21/9/2018 03:09:02] Loaded binding extension 'DurableTaskExtension' from 'referenced by: Method='TransformToRelational.Transform.RunTransformation', Parameter='context'.'
[21/9/2018 03:09:03] registered EventGrid Endpoint = http://localhost:7071/admin/extensions/EventGridExtensionConfig
[21/9/2018 03:09:03] Generating 3 job function(s)
[21/9/2018 03:09:03] Found the following functions:
[21/9/2018 03:09:03] TransformToRelational.Orchestrator.TransformOrchestration
[21/9/2018 03:09:03] TransformToRelational.Startup.Run
[21/9/2018 03:09:03] TransformToRelational.Transform.RunTransformation
[21/9/2018 03:09:03]
[21/9/2018 03:09:03] Host initialized (1353ms)
[21/9/2018 03:09:04] Host lock lease acquired by instance ID '00000000000000000000000059E1D128'.
[21/9/2018 03:09:04] Function started (Id=45f7d798-95a7-46c9-8769-8d17bf7fb18f)
[21/9/2018 03:09:04] Executing 'StartupFunc' (Reason='Timer fired at 2018-09-21T11:09:04.7440997+08:00', Id=45f7d798-95a7-46c9-8769-8d17bf7fb18f)
Debugger listening on [::]:5858
[21/9/2018 03:09:05] Function started (Id=6b83b8f2-0489-4fa0-a9be-9afb5179649c)
[21/9/2018 03:09:05] Executing 'TransformAndFormat' (Reason='', Id=6b83b8f2-0489-4fa0-a9be-9afb5179649c)
[21/9/2018 03:09:05] Function started (Id=c4ffc3ee-b02a-4786-a8ce-a8bb503b4523)
[21/9/2018 03:09:05] Executing 'TransformAndFormat' (Reason='', Id=c4ffc3ee-b02a-4786-a8ce-a8bb503b4523)
[21/9/2018 03:09:06] Function started (Id=ad33ef92-45eb-4759-b3ef-363b7fe95fd5)
[21/9/2018 03:09:06] Executing 'TransformAndFormat' (Reason='', Id=ad33ef92-45eb-4759-b3ef-363b7fe95fd5)
[21/9/2018 03:09:06] Function started (Id=b66452d4-04b8-4f32-b934-4ebcf7cfeed9)
[21/9/2018 03:09:06] Executing 'TransformAndFormat' (Reason='', Id=b66452d4-04b8-4f32-b934-4ebcf7cfeed9)
[21/9/2018 03:09:06] Function started (Id=bc4f7c77-10dc-4a2f-95b2-86de3a7199e6)
[21/9/2018 03:09:06] Executing 'TransformAndFormat' (Reason='', Id=bc4f7c77-10dc-4a2f-95b2-86de3a7199e6)
[21/9/2018 03:09:06] Function started (Id=f4e79a26-7cbb-44e9-a77f-df643990f89a)
[21/9/2018 03:09:06] Executing 'TransformAndFormat' (Reason='', Id=f4e79a26-7cbb-44e9-a77f-df643990f89a)
[21/9/2018 03:09:06] Function started (Id=2098e488-ba76-4684-afcb-31cb8789ee14)
[21/9/2018 03:09:06] Executing 'TransformAndFormat' (Reason='', Id=2098e488-ba76-4684-afcb-31cb8789ee14)
[21/9/2018 03:09:11] Function started (Id=5277d6bf-4024-40b9-b52f-d833d7fb8c81)
[21/9/2018 03:09:12] Function started (Id=476fe0b2-d577-4e97-9880-8cb7795efd44)
[21/9/2018 03:10:14] Executing 'TransformAndFormat' (Reason='', Id=476fe0b2-d577-4e97-9880-8cb7795efd44)
[21/9/2018 03:10:14] Executing 'TransformAndFormat' (Reason='', Id=5277d6bf-4024-40b9-b52f-d833d7fb8c81)
[21/9/2018 03:10:14] Function started (Id=05799036-9476-450f-abb6-f0fff061b225)
[21/9/2018 03:10:14] Function started (Id=3d486a91-17ff-4d80-86ee-74dc88599470)
[21/9/2018 03:10:14] Executing 'TransformAndFormat' (Reason='', Id=3d486a91-17ff-4d80-86ee-74dc88599470)
[21/9/2018 03:10:14] Function started (Id=110e9add-d7f5-4f5f-a0ef-242f4438ea39)
[21/9/2018 03:10:14] Executing 'TransformAndFormat' (Reason='', Id=110e9add-d7f5-4f5f-a0ef-242f4438ea39)
[21/9/2018 03:10:14] Function started (Id=022e6a88-8c54-4ea7-9f27-154200cd40f4)
[21/9/2018 03:10:14] Executing 'TransformAndFormat' (Reason='', Id=022e6a88-8c54-4ea7-9f27-154200cd40f4)
[21/9/2018 03:10:14] Function started (Id=f0c3e8a2-24f2-4e09-9043-3d50c1ecba16)
[21/9/2018 03:10:14] Executing 'TransformAndFormat' (Reason='', Id=f0c3e8a2-24f2-4e09-9043-3d50c1ecba16)
[21/9/2018 03:10:14] Function started (Id=99218445-2ce5-494a-a654-f8d4fbf11a95)
[21/9/2018 03:10:14] Executing 'TransformAndFormat' (Reason='', Id=99218445-2ce5-494a-a654-f8d4fbf11a95)
[21/9/2018 03:10:14] Executing 'TransformAndFormat' (Reason='', Id=05799036-9476-450f-abb6-f0fff061b225)
[21/9/2018 03:10:14] Function started (Id=a4f91185-6048-4d4a-b262-72d883af0425)
[21/9/2018 03:10:14] Executing 'TransformAndFormat' (Reason='', Id=a4f91185-6048-4d4a-b262-72d883af0425)
[21/9/2018 03:10:14] Function started (Id=1e981e76-c1f3-44c7-acff-1d4f3434b714)
[21/9/2018 03:10:14] Executing 'TransformAndFormat' (Reason='', Id=1e981e76-c1f3-44c7-acff-1d4f3434b714)
[21/9/2018 03:10:14] Function started (Id=28c01a28-762f-4ac6-99b6-04d203aa8494)
[21/9/2018 03:10:14] Executing 'TransformAndFormat' (Reason='', Id=28c01a28-762f-4ac6-99b6-04d203aa8494)
[21/9/2018 03:10:14] Function started (Id=797a4709-e6b7-499f-9d59-3341d6f07978)
[21/9/2018 03:10:14] Executing 'TransformAndFormat' (Reason='', Id=797a4709-e6b7-499f-9d59-3341d6f07978)
[21/9/2018 03:10:14] Function started (Id=8441563d-c2da-4524-b7e6-1f4cc020efbc)
[21/9/2018 03:10:14] Executing 'TransformAndFormat' (Reason='', Id=8441563d-c2da-4524-b7e6-1f4cc020efbc)
[21/9/2018 03:10:14] Function started (Id=6c8000c0-5ec2-4ca8-be56-95330ca23765)
[21/9/2018 03:10:14] Executing 'TransformAndFormat' (Reason='', Id=6c8000c0-5ec2-4ca8-be56-95330ca23765)
[21/9/2018 03:10:14] Function started (Id=27c68235-e52b-492c-a8bc-45e91b3929d1)
[21/9/2018 03:10:14] Executing 'TransformAndFormat' (Reason='', Id=27c68235-e52b-492c-a8bc-45e91b3929d1)
[21/9/2018 03:10:15] *** STARTUP FUNCTION *** - Time triggered
[21/9/2018 03:10:15] *** TRANSFORM FUNCTION - ACTIVITY *** executed at: 21/9/2018 11:10:15   (51f1ef294cf04351804736cae5f22a07)
[21/9/2018 03:10:15] *** TRANSFORM FUNCTION - ACTIVITY *** executed at: 21/9/2018 11:10:15   (76e3044b7a0849c18991b10fd6b34075)
[21/9/2018 03:10:15] *** TRANSFORM FUNCTION - ACTIVITY *** executed at: 21/9/2018 11:10:15   (ced17a0553c14d138c9feb7b72e44b50)
[21/9/2018 03:10:15] *** TRANSFORM FUNCTION - ACTIVITY *** executed at: 21/9/2018 11:10:15   (35cc4b30355049938c59aa8880d0203e)
[21/9/2018 03:10:15] *** TRANSFORM FUNCTION - ACTIVITY *** executed at: 21/9/2018 11:10:15   (d166b287697140b5beb80ba02109cfcb)
[21/9/2018 03:10:15] *** TRANSFORM FUNCTION - ACTIVITY *** executed at: 21/9/2018 11:10:15   (a8afa4ebc24c4a5596d36e32f7acb687)
[21/9/2018 03:10:15] *** TRANSFORM FUNCTION - ACTIVITY *** executed at: 21/9/2018 11:10:15   (57ef1d9f3e6649a9bc6f1628126b7f38)
[21/9/2018 03:10:15] *** TRANSFORM FUNCTION - ACTIVITY *** executed at: 21/9/2018 11:10:15   (bd3e3a2751cb48438c2465540dc61e97)
[21/9/2018 03:10:15] *** TRANSFORM FUNCTION - ACTIVITY *** executed at: 21/9/2018 11:10:15   (40dfd72548134412901a5ff2f7566cc2)
[21/9/2018 03:10:15] *** TRANSFORM FUNCTION - ACTIVITY *** executed at: 21/9/2018 11:10:15   (93b6ed9c00b04d9fb626c09d0b696d9c)
[21/9/2018 03:10:15] *** TRANSFORM FUNCTION - ACTIVITY *** executed at: 21/9/2018 11:10:15   (8fd9fb5c1ea94954896acf3780add1ad)
[21/9/2018 03:10:15] *** TRANSFORM FUNCTION - ACTIVITY *** executed at: 21/9/2018 11:10:15   (66401ebba4794869aebf043caab8c427)
[21/9/2018 03:10:15] *** TRANSFORM FUNCTION - ACTIVITY *** executed at: 21/9/2018 11:10:15   (fb6be8992f984e24b61237f3082ff54e)
[21/9/2018 03:10:15] *** TRANSFORM FUNCTION - ACTIVITY *** executed at: 21/9/2018 11:10:15   (e6c732ab6b7c4f57892ff7d95c952c8b)
[21/9/2018 03:10:15] *** TRANSFORM FUNCTION - ACTIVITY *** executed at: 21/9/2018 11:10:15   (90de278cf5a84cb981672a1c3432a5e4)
[21/9/2018 03:10:15] *** TRANSFORM FUNCTION - ACTIVITY *** executed at: 21/9/2018 11:10:15   (30825f010c3d4982a10f3a034d9adef7)
[21/9/2018 03:10:15] *** TRANSFORM FUNCTION - ACTIVITY *** executed at: 21/9/2018 11:10:15   (47e7aea0bc1e47fe970ef43bd6409baf)
[21/9/2018 03:10:15] *** TRANSFORM FUNCTION - ACTIVITY *** executed at: 21/9/2018 11:10:15   (1cca0179bdcc438b84a0a3b82a8ad807)
[21/9/2018 03:10:15] *** TRANSFORM FUNCTION - ACTIVITY *** executed at: 21/9/2018 11:10:15   (42ac98ba32e641afb92cd72cb4728b58)
[21/9/2018 03:10:15] *** TRANSFORM FUNCTION - ACTIVITY *** executed at: 21/9/2018 11:10:15   (f833676170834d4a936544b4ce6ba9d2)
[21/9/2018 03:10:15] *** TRANSFORM FUNCTION - ACTIVITY *** executed at: 21/9/2018 11:10:15   (f366d84806e34503bdb4ba7d982711aa)
[21/9/2018 03:10:15] *** TRANSFORM FUNCTION - ACTIVITY *** executed at: 21/9/2018 11:10:15   (d55121d270394755b88b4f34cd3b3c97)
[21/9/2018 03:10:17] ** Orchestration Start **
[21/9/2018 03:10:17] * 1  (57ef1d9f3e6649a9bc6f1628126b7f38)
[21/9/2018 03:10:17] * 1  (93b6ed9c00b04d9fb626c09d0b696d9c)
[21/9/2018 03:10:17] * 1  (ced17a0553c14d138c9feb7b72e44b50)
[21/9/2018 03:10:17] * 1  (d166b287697140b5beb80ba02109cfcb)
[21/9/2018 03:10:17] * 1  (51f1ef294cf04351804736cae5f22a07)
[21/9/2018 03:10:17] * 1  (40dfd72548134412901a5ff2f7566cc2)
[21/9/2018 03:10:17] ** Orchestration End **
[21/9/2018 03:10:17] Function completed (Success, Id=45f7d798-95a7-46c9-8769-8d17bf7fb18f, Duration=72573ms)
[21/9/2018 03:10:17] Executed 'StartupFunc' (Succeeded, Id=45f7d798-95a7-46c9-8769-8d17bf7fb18f)
[21/9/2018 03:10:17] The next 5 occurrences of the schedule will be:
[21/9/2018 03:10:17] 21/9/2018 11:15:00
[21/9/2018 03:10:17] 21/9/2018 11:20:00
[21/9/2018 03:10:17] 21/9/2018 11:25:00
[21/9/2018 03:10:17] 21/9/2018 11:30:00
[21/9/2018 03:10:17] 21/9/2018 11:35:00
[21/9/2018 03:10:17] * 1  (76e3044b7a0849c18991b10fd6b34075)
[21/9/2018 03:10:17] * 1  (35cc4b30355049938c59aa8880d0203e)
[21/9/2018 03:10:17] * 1  (a8afa4ebc24c4a5596d36e32f7acb687)
[21/9/2018 03:10:17] * 1  (bd3e3a2751cb48438c2465540dc61e97)
[21/9/2018 03:10:17] * 1  (8fd9fb5c1ea94954896acf3780add1ad)
[21/9/2018 03:10:17] * 1  (66401ebba4794869aebf043caab8c427)
[21/9/2018 03:10:17] * 1  (fb6be8992f984e24b61237f3082ff54e)
[21/9/2018 03:10:17] * 1  (e6c732ab6b7c4f57892ff7d95c952c8b)
[21/9/2018 03:10:17] * 1  (90de278cf5a84cb981672a1c3432a5e4)
[21/9/2018 03:10:17] * 1  (30825f010c3d4982a10f3a034d9adef7)
[21/9/2018 03:10:17] * 1  (47e7aea0bc1e47fe970ef43bd6409baf)
[21/9/2018 03:10:17] * 1  (1cca0179bdcc438b84a0a3b82a8ad807)
[21/9/2018 03:10:17] * 1  (42ac98ba32e641afb92cd72cb4728b58)
[21/9/2018 03:10:17] * 1  (f833676170834d4a936544b4ce6ba9d2)
[21/9/2018 03:10:17] * 1  (f366d84806e34503bdb4ba7d982711aa)
[21/9/2018 03:10:17] * 1  (d55121d270394755b88b4f34cd3b3c97)

Chris Gillum Chris Gillum · Accepted Answer · 2018-09-21T17:02:47

First of all, don't use RunOnStartup = true for your timer triggers. It will be removed in future versions because it causes lots of problems and confusion for people. It might be related to the problem you're seeing.

What you're describing sounds like you've created a bunch of orchestrations in the past which have not yet completed, and these activity executions correspond to these old, uncompleted orchestrations. Orchestrations are durable and long-running, so they will continue to try to run until they complete or fail, even after you shut down your function app and restart it.

If you want to start from a clean slate, either change the name of your task hub or delete all the messages in your Azure Storage queues.

Azure Durable function. orchestration spawns many unwanted activities

1 Answers