search

Azure / azure-functions-powershell-library

MIT License
2 stars 3 forks source link

Bug bash: CurrentUtcDateTime not getting updated with DurableTimers #40

Open michaelpeng36 opened 2 years ago

michaelpeng36 commented 2 years ago

Using template definitions for the HTTP Start function, an orchestrator with the following code

function DurableFunctionsOrchestrator1 { 
    [Function()] 
    param( 
        [OrchestrationTrigger()] 
        $Context
    ) 

    # $output = @() 
    # $task1 = Invoke-DurableActivity -FunctionName 'Hello1' -Input 'Tokyo' -NoWait
    # $task2 = Invoke-DurableActivity -FunctionName 'Hello1' -Input 'Seattle' -NoWait
    # $task3 = Invoke-DurableActivity -FunctionName 'Hello1' -Input 'London' -NoWait
    # $output += Wait-DurableTask -Task @($task1, $task2, $task3) -Any

    $timer1 = Start-DurableTimer -Duration (New-Timespan -Seconds 10) -nowait
    Write-Host "Started durable timer1 at $($Context.CurrentUtcDateTime)"
    $timer2 = Start-DurableTimer -Duration (New-Timespan -Seconds 5) -nowait
    Write-Host "Started durable timer 2 $($Context.CurrentUtcDateTime)"
    $output += Wait-DurableTask -Task @($timer1, $timer2) -Any
    Write-Host "Finished awaiting timers at $($Context.CurrentUtcDateTime)"
    Stop-DurableTimerTask -Task $timer1
    Write-Host 'Stopped durable timer'

    $output
}

Will not have the $Context.CurrentUtcDateTime update after the timer is awaited. Here are the corresponding logs:

Azure Functions Core Tools
Core Tools Version:       4.0.4833 Commit hash: N/A  (64-bit)
Function Runtime Version: 4.11.2.19273

[2022-10-13T20:46:40.633Z] Worker process started and initialized.

Functions:

        DurableFunctionsHttpStart1: [GET,POST] http://localhost:7071/api/DurableStart

        HttpTriggerMinimal: [GET,POST] http://localhost:7071/api/HttpTriggerMinimal

        Trig: [GET,POST] http://localhost:7071/api/rerouted

        DurableFunctionsOrchestrator1: orchestrationTrigger

        Hello1: activityTrigger

For detailed output, run func with --verbose flag.
[2022-10-13T20:46:41.594Z] Host lock lease acquired by instance ID '000000000000000000000000FE55AF73'.
[2022-10-13T20:47:01.540Z] Executing 'Functions.DurableFunctionsHttpStart1' (Reason='This function was programmatically called via the host APIs.', Id=dddd86c0-e61a-4863-a71a-8efddaf53503)
[2022-10-13T20:47:03.265Z] INFORMATION: Started orchestration with ID = '42bcad0f-69aa-49dd-b503-a063d46cc1cf'
[2022-10-13T20:47:03.453Z] Executing 'Functions.DurableFunctionsOrchestrator1' (Reason='(null)', Id=8d801bde-baec-4e4b-8c8f-a000da6e8fda)
[2022-10-13T20:47:03.683Z] Executed 'Functions.DurableFunctionsHttpStart1' (Succeeded, Id=dddd86c0-e61a-4863-a71a-8efddaf53503, Duration=2396ms)
[2022-10-13T20:47:03.845Z] Executed 'Functions.DurableFunctionsOrchestrator1' (Succeeded, Id=8d801bde-baec-4e4b-8c8f-a000da6e8fda, Duration=408ms)
[2022-10-13T20:47:03.978Z] Executing 'Functions.Hello1' (Reason='(null)', Id=98fd6399-9d15-4e70-ba0e-55252b0707e7)
[2022-10-13T20:47:03.978Z] Executing 'Functions.Hello1' (Reason='(null)', Id=e3a82680-f8b8-46ff-8b2a-45c8d5ba086d)
[2022-10-13T20:47:03.978Z] Executing 'Functions.Hello1' (Reason='(null)', Id=6220f997-a32b-46e8-b4ac-171da593ac7b)
[2022-10-13T20:47:04.035Z] Executed 'Functions.Hello1' (Succeeded, Id=98fd6399-9d15-4e70-ba0e-55252b0707e7, Duration=63ms)
[2022-10-13T20:47:04.069Z] Executed 'Functions.Hello1' (Succeeded, Id=6220f997-a32b-46e8-b4ac-171da593ac7b, Duration=97ms)
[2022-10-13T20:47:04.165Z] Executing 'Functions.DurableFunctionsOrchestrator1' (Reason='(null)', Id=d0abb2e1-7574-4d26-8f77-cce4c39ad063)
[2022-10-13T20:47:04.170Z] Executed 'Functions.Hello1' (Succeeded, Id=e3a82680-f8b8-46ff-8b2a-45c8d5ba086d, Duration=197ms)
[2022-10-13T20:47:04.223Z] INFORMATION: Started durable timer1 at 10/13/2022 20:47:04
[2022-10-13T20:47:04.226Z] INFORMATION: Started durable timer 2 10/13/2022 20:47:04
[2022-10-13T20:47:04.289Z] Executed 'Functions.DurableFunctionsOrchestrator1' (Succeeded, Id=d0abb2e1-7574-4d26-8f77-cce4c39ad063, Duration=130ms)
[2022-10-13T20:47:04.380Z] Executing 'Functions.DurableFunctionsOrchestrator1' (Reason='(null)', Id=892d33d6-095a-4436-92be-6c1d1fc9e65b)
[2022-10-13T20:47:04.454Z] INFORMATION: Started durable timer1 at 10/13/2022 20:47:04
[2022-10-13T20:47:04.458Z] INFORMATION: Started durable timer 2 10/13/2022 20:47:04
[2022-10-13T20:47:04.498Z] Executed 'Functions.DurableFunctionsOrchestrator1' (Succeeded, Id=892d33d6-095a-4436-92be-6c1d1fc9e65b, Duration=142ms)
[2022-10-13T20:47:10.371Z] Executing 'Functions.DurableFunctionsOrchestrator1' (Reason='(null)', Id=469166b7-4d78-434c-b7b8-ceae00b77a1d)
[2022-10-13T20:47:10.386Z] INFORMATION: Started durable timer1 at 10/13/2022 20:47:04
[2022-10-13T20:47:10.390Z] INFORMATION: Started durable timer 2 10/13/2022 20:47:04
[2022-10-13T20:47:10.393Z] INFORMATION: Finished awaiting timers at 10/13/2022 20:47:04
[2022-10-13T20:47:10.396Z] INFORMATION: Stopped durable timer
[2022-10-13T20:47:10.468Z] OUTPUT: Microsoft.Azure.Functions.PowerShellWorker.Durable.Tasks.ActivityInvocationTask
[2022-10-13T20:47:10.472Z] OUTPUT: Microsoft.Azure.Functions.PowerShellWorker.Durable.Tasks.DurableTimerTask
[2022-10-13T20:47:10.564Z] Executed 'Functions.DurableFunctionsOrchestrator1' (Succeeded, Id=469166b7-4d78-434c-b7b8-ceae00b77a1d, Duration=193ms)