locked
Strange Execution Order For Durable Functions RRS feed

  • Question

  • Hello,

    I'm having a strange order of execution for my durable function.  I have created a really simple function with a timer, an orchestrator, and an activity function.

    The order of execution should be:

    1) Timer 
    2) Orchestrator
    3) Activity.

    For some reason it's executing randomly.  Here is my sample source code:

           [FunctionName("Function1")]
            public static void Run(
                [TimerTrigger("0 */1 * * * *")]TimerInfo myTimer,
                [OrchestrationClient] DurableOrchestrationClient starter,
                TraceWriter log)
            {
                log.Info("1) Starting MyOrchestrator");
                starter.StartNewAsync("MyOrchestrator", null);
                log.Info("6) Ending MyOrchestrator");
            }
    
            [FunctionName("MyOrchestrator")]
            public static async Task<bool> MyOrchestrator(
            [OrchestrationTrigger] DurableOrchestrationContext backupContext,
            TraceWriter log)
            {
                log.Info("2) HERE IN MyOrchestrator");
                log.Info("3) BEFORE CALLING MyActivity1");
                var Result = await backupContext.CallActivityAsync<bool>("MyActivity1", "Hello");
                log.Info("5) AFTER CALLING MyActivity1");
    
                return true;
            }
    
            [FunctionName("MyActivity1")]
            public static bool MyActivity1(
                [ActivityTrigger] string SomeString,
                TraceWriter log)
            {
                log.Info("4) HERE IN MyActivity1");
                return true;
            }

    Here is my trace log output (I highlighted the outputs in bold):

    [6/26/2018 6:01:40 PM] 1) Starting MyOrchestrator
    [6/26/2018 6:01:40 PM] 6) Ending MyOrchestrator
    [6/26/2018 6:01:40 PM] Function completed (Success, Id=28546e67-2c79-4262-a1fb-9fbe6e616c7f, Duration=374ms)
    [6/26/2018 6:01:40 PM] Executed 'Function1' (Succeeded, Id=28546e67-2c79-4262-a1fb-9fbe6e616c7f)
    [6/26/2018 6:01:40 PM] The next 5 occurrences of the schedule will be:
    [6/26/2018 6:01:40 PM] 6/26/2018 1:02:00 PM
    [6/26/2018 6:01:40 PM] 6/26/2018 1:03:00 PM
    [6/26/2018 6:01:40 PM] 6/26/2018 1:04:00 PM
    [6/26/2018 6:01:40 PM] 6/26/2018 1:05:00 PM
    [6/26/2018 6:01:40 PM] 6/26/2018 1:06:00 PM
    [6/26/2018 6:01:40 PM]
    [6/26/2018 6:01:41 PM] Host started (2547ms)
    [6/26/2018 6:01:41 PM] Job host started
    [6/26/2018 6:01:41 PM] Function started (Id=822b15f7-beaf-47d9-9945-2dec421ea799)
    [6/26/2018 6:01:41 PM] Executing 'MyActivity1' (Reason='', Id=822b15f7-beaf-47d9-9945-2dec421ea799)
    [6/26/2018 6:01:41 PM] 4) HERE IN MyActivity1
    [6/26/2018 6:01:41 PM] Function completed (Success, Id=822b15f7-beaf-47d9-9945-2dec421ea799, Duration=17ms)
    [6/26/2018 6:01:41 PM] Executed 'MyActivity1' (Succeeded, Id=822b15f7-beaf-47d9-9945-2dec421ea799)
    [6/26/2018 6:01:41 PM] Function started (Id=8810f26c-3212-4ec1-83b9-a03d8dfb5dee)
    [6/26/2018 6:01:41 PM] Executing 'MyOrchestrator' (Reason='', Id=8810f26c-3212-4ec1-83b9-a03d8dfb5dee)
    [6/26/2018 6:01:41 PM] 2) HERE IN MyOrchestrator
    [6/26/2018 6:01:41 PM] 3) BEFORE CALLING MyActivity1
    [6/26/2018 6:01:41 PM] Function completed (Success, Id=8810f26c-3212-4ec1-83b9-a03d8dfb5dee, Duration=45ms)
    [6/26/2018 6:01:41 PM] Executed 'MyOrchestrator' (Succeeded, Id=8810f26c-3212-4ec1-83b9-a03d8dfb5dee)
    [6/26/2018 6:01:41 PM] Function started (Id=d7af121c-bc90-4617-a48b-aea36e026e94)
    [6/26/2018 6:01:41 PM] Executing 'MyOrchestrator' (Reason='', Id=d7af121c-bc90-4617-a48b-aea36e026e94)
    [6/26/2018 6:01:41 PM] 2) HERE IN MyOrchestrator
    [6/26/2018 6:01:41 PM] 3) BEFORE CALLING MyActivity1
    [6/26/2018 6:01:41 PM] 5) AFTER CALLING MyActivity1
    [6/26/2018 6:01:41 PM] Function completed (Success, Id=d7af121c-bc90-4617-a48b-aea36e026e94, Duration=9ms)
    [6/26/2018 6:01:41 PM] Executed 'MyOrchestrator' (Succeeded, Id=d7af121c-bc90-4617-a48b-aea36e026e94)
    Debugger listening on [::]:5858

    Does anyone know why it executes randomly like this?

    Thanks



    • Edited by Ryan_Ha Tuesday, June 26, 2018 6:14 PM
    Tuesday, June 26, 2018 6:11 PM

All replies

  • Nevermind, I realized this is just because the Tracewriters were writing during a replay.

    I changed this function and it works better now

            [FunctionName("MyOrchestrator")]
            public static async Task<bool> MyOrchestrator(
            [OrchestrationTrigger] DurableOrchestrationContext backupContext,
            TraceWriter log)
            {
                if (!backupContext.IsReplaying)
                     {
                   log.Info("2) HERE IN MyOrchestrator");
                   log.Info("3) BEFORE CALLING MyActivity1");
                      }
    
                var Result = await backupContext.CallActivityAsync<bool>("MyActivity1", "Hello");
                
                if (!backupContext.IsReplaying)
                     log.Info("5) AFTER CALLING MyActivity1");
    
                return true;
            }

    Tuesday, June 26, 2018 8:50 PM