Search code examples
azurepowershellazure-functionsazure-durable-functions

Azure Durable Functions PowerShell - Strange orchestrator behavior


I am currently facing a strange behavior with azure durable functions, based on powershell. I tried to debug it and also searched the Microsoft docs/Internet for similar cases. But i am still left with a question mark in my mind regarding that orchestrator behavior.

The orchestrator is executing my durable activity function in a strange and unexpected way and reruns itself over and over again.

Let me introduce you into my code real quick and show my problem here:

Orchestrator:

param($Context)
$ErrorActionPreference = "Stop"
$output = @()

try {
    #Validate Input
    Write-Information "Orchestrator: Validating Input"
    $JSONString = ($Context.Input).ToString()
    if (-not ([string]::IsNullOrEmpty($JSONString))) {
        $InputPSObject = ConvertFrom-Json $JSONString

        try {
            $TestFunction = Invoke-DurableActivity -FunctionName ‘TestFunction’ -Input $InputPSObject
        }
        catch {
            Write-Warning "Orchestrator: Test Function: $($_.Exception.Message)"
        } 

    } else {
        Write-Error "Orchestrator: Could not validate Input. String is null or empty"
        throw
    }
} catch {
    Write-Error "Orchestrator: Could not validate Input. Unexpected error"
    Write-Warning "Orchestrator: $($_.Exception.Message)"
    throw
}

Test durable function

param($InputObject)
Write-Information: “TestFunction”
$ErrorActionPreference = "Continue"

if ($test) {

  $array = @()
try {
  ..do someting..
  if ($Object -eq "Test") {
    $array += $Object
  } else {
    Write-Warning "Object is empty"
  }
  return $array
}
catch {
  Write-Warning "Unexpected error"
}
}

FYI: The function is more or less a example of my real function, so don’t get confused here. But it should be enough code to introduce you to the issue.

Cutout of the execution log stream:

INFORMATION: Orchestrator: Validating Input
INFORMATION: TestFunction
WARNING: Object is empty
INFORMATION: Orchestrator: Validating Input
WARNING: Orchestrator: Test Function: Value cannot be null. (Parameter 'input').
Executed 'Functions.TestOrchestrator (Succeeded, Id=***, Duration=95ms)

Behavior /Explanation: The functions is trigger by a HTTP trigger (JSON file is transmitted in the http body) and the orchestrator executes the durable function (like expected)

INFORMATION: Orchestrator: Validating Input
INFORMATION: TestFunction

Then a “error" happens in the durable “Test function”. But no problem, the error is catched (like expected), only a Warning message is display in the log stream:

WARNING: Object is empty

Up to here it is still expected behavior, an empty array is returned to the orchestrator (Because it could not fill in any values due to the error). But then it gets confusing: The orchestrator runs again from the beginning, this can be seen through the log stream:

INFORMATION: Orchestrator: Validating Input

And jumps again into the try block of the try-catch function and trys to reexecute the test durable function (That can be verify through debugging in vscode.) FYI: There is no retry option in the orchestrator! But the second execution of the functions fails directly and he gets in the catch block. I have no idea why he thinks the "input" of the function is empty now? This can also be seen in the log stream:

WARNING: Orchestrator: Test Function: Value cannot be null. (Parameter 'input').

In my productive azure function I have more than one activity function and he will repeat that behavior for every other executed function. So after every other executed function he will try to execute the “TestFunction” again and fails again with this log stream message:

INFORMATION: Orchestrator: Validating Input
WARNING: Orchestrator: Test Function: Value cannot be null. (Parameter 'input').

It seems like a very strange behavior, but maybe it is a “normal” expected behavior of the orchestrator, I am not aware of. I would be glad if some could explain that to me so I am able to handle that behavior better :)

Thank you very much

EDIT: The HTTP Trigger code, as requested by @Ikhtesam Afrin:

HTTP Trigger

using namespace System.Net

param($Request, $TriggerMetadata)

$FunctionName = $Request.Params.FunctionName
$Body = $Request.Body
$InstanceId = Start-DurableOrchestration -FunctionName $FunctionName -InputObject $Body
Write-Host "Started orchestration with ID = '$InstanceId'"

$Response = New-DurableOrchestrationCheckStatusResponse -Request $Request -InstanceId $InstanceId
Push-OutputBinding -Name Response -Value $Response

Solution

  • It seems like a very strange behavior, but maybe it is a “normal” expected behavior of the orchestrator, I am not aware of.

    Yes, it is an expected behavior of orchestrator function.

    • Refer to this MS Doc which says the below.

    enter image description here

    • Even I can see, Orchestrator function executed twice.

    enter image description here

    • If you will open the first run, you will see State: Scheduled, RuntimeStatus: Pending.

    enter image description here

    • Meanwhile if you will check the activity function completion time, you will see it has completed after the first run of Orchestrator function.

    enter image description here

    • So, the Orchestrator function executed again after the completion of activity function in order to update the status in the History table which is State: Completed, RuntimeStatus: Completed.

    enter image description here

    • Orchestrator function will execute until the state is updated to completed.