Azure Durable orchestration function ILogger outputs logs twice

Question

There are couple of durable functions that call each other. Main orchestration -> Sub orchestration -> Activity -> Helper async method

Each func has ILogger dependency and log on function start and on function end. Both orchestrators duplicates "on start" message for some reason. (See pic) Activity does not have this effect. (See pic) Ran example below many times - same story.

I am also sure that the whole process has been triggered once.

Is this a bug in orchestrators or expected behavior?

using System;
using System.Net.Http;
using System.Threading.Tasks;
using Microsoft.AspNetCore.Mvc;
using Microsoft.Azure.WebJobs;
using Microsoft.Azure.WebJobs.Extensions.DurableTask;
using Microsoft.Azure.WebJobs.Extensions.Http;
using Microsoft.Extensions.Logging;

namespace Issues
{
    public static class Log_Issue
    {
        [FunctionName("Main")]
        public static async Task RunOrchestrator(
            [OrchestrationTrigger] IDurableOrchestrationContext context,
            ILogger log)
        {
            try
            {
                log.LogWarning("Main Start");
                await context.CallSubOrchestratorAsync("Sub", null);
                log.LogWarning("Main End");
            }
            catch (Exception e)
            {
                Console.WriteLine(e);
                throw;
            }
        }

        [FunctionName("Sub")]
        public static async Task RunSubOrchestrator(
            [OrchestrationTrigger] IDurableOrchestrationContext context,
            ILogger log)
        {
            log.LogWarning("Sub Start");
            var data = await context.CallActivityAsync<string>("Activity", null);
            log.LogWarning("Sub End");
        }

        [FunctionName("Activity")]
        public static async Task<string> GetDataActivity([ActivityTrigger] string name, ILogger log)
        {
            log.LogWarning("Activity Start");
            var data = await GetDataAsync("https://www.google.com");
            log.LogWarning("Activity End");

            return data;
        }

        [FunctionName("Start")]
        public static async Task<IActionResult> HttpStart(
            [HttpTrigger(AuthorizationLevel.Anonymous, "get", "post")]
            HttpRequestMessage req,
            [DurableClient] IDurableOrchestrationClient starter,
            ILogger log)
        {
            var instanceId = await starter.StartNewAsync("Main", null);
            log.LogWarning($"Started orchestration with ID = '{instanceId}'.");
            return new OkResult();
        }

        private static async Task<string> GetDataAsync(string url)
        {
            var httpClient = new HttpClient();

            using var request = new HttpRequestMessage
            {
                RequestUri = new Uri(url),
                Method = HttpMethod.Get,
            };

            var response = await httpClient.SendAsync(request);
            response.EnsureSuccessStatusCode();

            return await response.Content.ReadAsStringAsync();
        }
    }
}

Answer 1

This is expected. For example on await context.CallActivityAsync("Activity", null); The code pauses itself and may even be loaded out of memory (in order to save on cost).

Then the orchestrator waits for an event to be placed in another Azure Storage Table which the activity creates, this may occur many days later. For activities they are usually very instant but it still waits for this event to occur.

When that happens the code needs to start from where it last stopped but there is no way to do that. Therefor the code reruns from the beginning but instead of waiting for the activity to finish again it first looks in the table and sees that we already have done this activity and can continue running. If the activity function returned some value it would be returned from the await call. During both runs of the orchestrator it would log but since we only go inte the activity ones that would only be logged ones.

This is why orchestrators have to be deterministic since e.g. a random value on the first run would not be the same as during the second run. Instead we would put the random.Next() into an activity funtion so that the value is saved to Azure Table Storage to be used on subsequent reruns. The orchestrator could also be waiting for some external events which normal functions create. E.g someone has to verify their email account which could take some number of days and this is why durable functions can unload themself and restart when they are triggered by the event.

Answer 2

All that @FilipB said is true. It is just missing the actual code to solve it ;)

[FunctionName("Main")]
public static async Task RunOrchestrator(
[OrchestrationTrigger] IDurableOrchestrationContext context,
ILogger log)
{
    log = context.CreateReplaySafeLogger(log); // this is what you should use at the start of every Orchestrator