Durable activity failures still not working properly in Fan out/Fan in orchestrator

ruankrTs commented 1 year ago

tl;dr: When using Fan out/fan in pattern, and one or more activity fails, the final output in the orchestrator function is dropped.

Still not able to handle activity errors in an orchestrator function when using the fan/out fan/in pattern. Although it seems to report the failure there is no way to get a working output for combinations of successful and failed activities at all. It either discards the successful output, or ignores the failure. Using same code to above issue but using the new SDK.

Trigger (Service Bus)

param([string] $SbMsg, $TriggerMetadata)
$ErrorActionPreference = "Stop"

<#
Service bus message received:
{
  "TestFilter": {
    "version": "1.0.0",
    "environment": "testEnv",
    "itemName": [
      "test1",
      "test2",
      "test3",
      "test4",
      "test5"
    ],
    "appComponent": "testcomponent",
    "application": "testApp"
  }
}
#>

# Declare 5 cities to be randomly picked later
$city = @("London", "Paris", "New York", "Tokyo", "Sydney")

# Create a hashtable the orchestrator could use to iterate over
foreach ($item in $TriggerMetadata.TestFilter.itemName) {
    $hashtableout += @{
        $item = @{
            city     = $city | Get-Random
            itemName = $item
        }
    }
}

# Start the orchestration
$InstanceId = Start-DurableOrchestration -FunctionName "of-test" -Input $hashtableout -ErrorAction Stop
Write-Host "Started orchestration with ID = '$InstanceId'"

Activity Function

param($name)
$ErrorActionPreference = 'Stop'

$actStopwatch = [System.Diagnostics.Stopwatch]::StartNew()

if ($($name.itemName) -eq "test3") { throw }
elseif ($($name.itemName) -eq "test1") { Start-Sleep -Seconds  3}
elseif ($($name.itemName) -eq "test5") { Start-Sleep -Seconds 8 }
elseif ($($name.itemName) -eq "test4") { Start-Sleep -Seconds 50 }

# Finalise outputs
$actStopwatch.stop()
[decimal]$elapsedSecods = $actStopwatch.Elapsed.TotalMinutes
$actTotalTime = "{0:N2}" -f $elapsedSecods
Write-Information -MessageData "[$($name.itemName)] Completed in [$actTotalTime]..."
$name.add('runResults', "Deployment Succeeded. Runtime [$actTotalTime]")
"[$($name.itemName)] Completed in [$actTotalTime]"

So when using the below Orchestrator code everything works as expected regarding the error handling and getting final output from the orchestrator function. The orchestrator schedules the tasks and the final output includes any successful activity outputs as well as failures caught and handled within the orchestrator function. The problem with this orchestrator pattern however is the tasks are asynchronous and therefore do not run efficiently in that they queue behind each other (using sleep statements in the activity highlights this as can be seen below in the scheduled times)

Orchestrator (Working error handling, but pattern not optimal)

using namespace System.Net

param($Context)

$ErrorActionPreference = 'Stop'

$output = @()

foreach ($property in $Context.Input.psobject.properties.name) {
    # invoke the activity function
    try {
        $output += Invoke-DurableActivity -FunctionName "af-test" -Input $Context.Input.$property
    }
    catch {
        $output += "[$($property)] Failed"
    }
}

return $output

So the final output highlights the failure meaning the catch block works as expected BUT the scheduling of activities is done in series (function chaining) and therefore causes a completion time build up (last activity might run quickest but has to wait for all others to complete first)

Changing to the Fan out/fan in pattern, the behaviour changes:

using namespace System.Net

param($Context)

$ErrorActionPreference = 'Stop'

$output = @()

$ParallelTasks =
foreach ($property in $Context.Input.psobject.properties.name) {
    # invoke the activity function
    try {
        Invoke-DurableActivity -FunctionName "af-test" -Input $Context.Input.$property -NoWait
    }
    catch {
        $output += "[$($property)] Failed"
    }
}

$output += Wait-DurableTask -Task $ParallelTasks

return $output

And produces this error:

Changing to $ErrorActionPreference = 'Continue' allows the orchestrator to complete, but there is no output returned:

Moving the try/catch works partially in that it seems to capture the failures, but disregards the successful runs from the output:

using namespace System.Net

param($Context)

$ErrorActionPreference = 'Stop'

$output = @()

$ParallelTasks =
foreach ($property in $Context.Input.psobject.properties.name) {
    # invoke the activity function
    Invoke-DurableActivity -FunctionName "af-test" -Input $Context.Input.$property -NoWait
}

try {
    $output += Wait-DurableTask -Task $ParallelTasks
}
catch {
    $output += "[$($property)] Failed"
}

return $output

It also does not collect multiple failures:

Using the same logic as in the fan out/fan in section here: https://github.com/Azure/azure-functions-durable-powershell/blob/main/test/E2E/durableApp/DurablePatternsOrchestrator/run.ps1 .

using namespace System.Net

param($Context)

$ErrorActionPreference = 'Continue'

$output = @()

$ParallelTasks = @()

foreach ($property in $Context.Input.psobject.properties.name) {
    # invoke the activity function
    try {
        $ParallelTasks += Invoke-DurableActivity -FunctionName "af-test" -Input $Context.Input.$property -NoWait
    }
    catch {
        $ParallelTasks += "[$($property)] Failed"
    }
}

$output += Wait-DurableTask -Task $ParallelTasks

return $output

Again runs successfully, but does not handle the error or produce any final output. However, using this same orchestrator code but with no failing activities works and produces the final output:

So, to me it seems that whenever one or more activities fail, it just nukes any final output or captures only one.

I've tried relentlessly but cannot get the Fan out/fan in orchestrator to properly output when activities fail. I've also tried setting various different options for the $ErrorActionPreference to no avail. Would be great if error handling could work similar to when the chaining pattern is used and final output is generated with success or failures or both. Or perhaps there is a way to individually query the task results when using the Fan out/fan in pattern to achieve a similar result?

ruankrTs commented 1 year ago

@davidmrdavid Did you see my comments above? Am I wasting time with trying sdk as seems there's no movement or responses on it at all in over a month?

davidmrdavid commented 1 year ago

Hi @ruankr,

I'm sorry for the delayed response, it has been an unexpectedly busy time for the team and therefore I've been lagging severely behind my GitHub notifications; that's on me.

After your latest comment, I think I understand what you're trying to achieve with the fanning pattern. I have a coding snippet that I think achieves what you need, but first I want to clarify a few conceptual bits that should explain why previous attempts did not work.

I'll begin by clarifying some behaviors:

(1) The `Wait-DurableTask` CmdLet returns a list of the results of its subtasks if and only if all of its subtasks complete without an exception. Otherwise, the CmdLet will throw an exception.

This is the expected behavior and is consistent with how Durable Functions works in other languages. Therefore, if you want to capture all results in a way that tolerates failure, you will need a try-catch of some kind.

As an aside: if I recall correctly, the buggy behavior that's fixed in this SDK is that previously if some subtasks failed while others succeeded, it was possible for the commandlet to still return a list of subtasks instead of throwing an exception.

(2) The argument to `Wait-DurableTask` are Durable Task objects, not arbitrary code.

This explains why the following piece of code did not work for you:

using namespace System.Net

param($Context)

$ErrorActionPreference = 'Stop'

$output = @()

$ParallelTasks =
foreach ($property in $Context.Input.psobject.properties.name) {
    # invoke the activity function
    try {
        Invoke-DurableActivity -FunctionName "af-test" -Input $Context.Input.$property -NoWait
    }
    catch {
        $output += "[$($property)] Failed"
    }
}

$output += Wait-DurableTask -Task $ParallelTasks

return $output

In the snippet above, you are calling Invoke-DurableActivity with the -NoWait flag, which means that instead of scheduling the activity at that moment, we will defer scheduling it and instead just create a task object that another CmdLet (Wait-DurableTask in this case) can use to schedule the activity. Therefore, the try-catch block there is not actually checking if the activity code produced an exception, it is checking if producing the task failed, which is highly unlikely.

Therefore, the code above is equivalent to not having a try-catch at all, as if you had written the code below.

using namespace System.Net

param($Context)

$ErrorActionPreference = 'Stop'

$output = @()

$ParallelTasks =
foreach ($property in $Context.Input.psobject.properties.name) {
    # invoke the activity function
    Invoke-DurableActivity -FunctionName "af-test" -Input $Context.Input.$property -NoWait # This code does not throw exceptions
}

$output += Wait-DurableTask -Task $ParallelTasks

return $output

So with this background, I think you were on the right track with placing the try-catch around the Wait-DurableTask invocation, but some tweaks are needed. Please try out the snippet below, which is explained inlined in the form of comments:


# ... after creating your tasks and collecting them inside a $parallelTasks variable

try {
    # schedule the tasks. If they all succeed, they will be collected in the $output variable
    $output = Wait-DurableTask -Task $parallelTasks
}
catch {
    # if we're here, then at least one of the $parallelTasks failed.
    # now we need to collect tasks individually, protecting against exceptions
    foreach ($task in $parallelTasks) { # for each scheduled sub task
        try {
            # try to get the result of the task. If the result is an exception, it will throw it
            $result = Get-DurableTaskResult -Task $task
            # if we're here, the result is not an exception, so we add it to the list
            $output += $result
        }
        catch {
            # if we're here, the result is an exception, so we opt to add its error message to the list.
            $output += $_.Exception.Message
        }
    }
}

Hopefully the comments above help explain how this snippet achieves its goal. At this point, I'm not certain that there's a bug per se on the pattern itself, though I realize we could have more convenience CmdLets for achieving the specific output you're aiming to collect. Please let me know if the snippet above makes sense and if works for you. Thanks.

ruankrTs commented 1 year ago

@davidmrdavid Thanks for the reply. I've been doing some testing and managed to get it working with some slight adjustments as below:

Trigger:

param([string] $SbMsg, $TriggerMetadata)
$ErrorActionPreference = "Stop"

<#
Service bus message received:
{
  "TestFilter": {
    "version": "1.0.0",
    "environment": "testEnv",
    "itemName": [
      "test1",
      "test2",
      "test3",
      "test4",
      "test5"
    ],
    "appComponent": "testcomponent",
    "application": "testApp"
  }
}
#>

# Declare 5 cities to be randomly picked later
$city = @("London", "Paris", "New York", "Tokyo", "Sydney")

# Create a hashtable the orchestrator could use to iterate over
foreach ($item in $TriggerMetadata.TestFilter.itemName) {
    $hashtableout += @{
        $item = @{
            city     = $city | Get-Random
            itemName = $item
        }
    }
}

# Start the orchestration
$InstanceId = Start-DurableOrchestration -FunctionName "of-test-orchestrator" -Input $hashtableout -ErrorAction Stop
Write-Host "Started orchestration with ID = '$InstanceId'"

Orchestrator:

using namespace System.Net

param($Context)

$ErrorActionPreference = 'Stop'

$finalOutput = @{
    Success = @()
    Failed  = @()
}

$output = @()

$parallelTasks =
foreach ($property in $Context.Input.psobject.properties.name) {
    # invoke the activity function
    Invoke-DurableActivity -FunctionName "af-test-activity1" -Input $Context.Input.$property -NoWait
}

try {
    # schedule the tasks. If they all succeed, they will be collected in the $output variable
    $output = Wait-DurableTask -Task $parallelTasks
    foreach ($out in $output) {
        $finalOutput.Success += $out
    }
}
catch {
    # if we're here, then at least one of the $parallelTasks failed.
    # now we need to collect tasks individually, protecting against exceptions
    foreach ($task in $parallelTasks) {
        # for each scheduled sub task
        try {
            # try to get the result of the task. If the result is an exception, it will throw it
            $result = Get-DurableTaskResult -Task $task
            $finalOutput.Success += $result
        }
        catch {
            # if we're here, the result is an exception, so we opt to add its error message to the list.
            $failedItem = $_.Exception.Message.Split("[").Split("]")[1]
            $finalOutput.Failed += "[$($failedItem)] Failed"
        }
    }
}

# Set orchestrator custom status
if ($finalOutput.Failed.Count -gt 0 -and $finalOutput.Success.Count -gt 0) {
    Set-DurableCustomStatus -CustomStatus "Orchestration Part Failed"
}
elseif ($finalOutput.Failed.Count -eq 0 -and $finalOutput.Success.Count -gt 0) {
    Set-DurableCustomStatus -CustomStatus "Orchestration Succeeded"
}
elseif ($finalOutput.Failed.Count -gt 0 -and $finalOutput.Success.Count -eq 0) {
    Set-DurableCustomStatus -CustomStatus "Orchestration Failed"
}

$finalOutput

Activity

param($afItems)

try {
    $ErrorActionPreference = 'Stop'

    $actStopwatch = [System.Diagnostics.Stopwatch]::StartNew()

    $ranSecs = Get-Random -Minimum 10 -Maximum 100

    if ($($afItems.itemName) -eq "test-item-32") { throw "$($afItems.itemName) - Is failing" }
    elseif ($($afItems.itemName) -eq "test-item-41") { throw "$($afItems.itemName) also failed" }
    elseif ($($afItems.itemName) -eq "test-item-50") { Start-Sleep -Seconds 320 }
    else { Start-Sleep -Seconds $ranSecs }

    # Finalise outputs
    $actStopwatch.stop()
    [decimal]$elapsedSecods = $actStopwatch.Elapsed.TotalMinutes
    $actTotalTime = "{0:N2}" -f $elapsedSecods
    Write-Information -MessageData "$($afItems.itemName) completed in [$actTotalTime]"

    return "[$($afItems.itemName)] Completed. runTime($($actTotalTime))"

}
catch {
    $errItem = $_.Exception
    $errLine = $_.InvocationInfo.ScriptLineNumber
    $errMsg = $errItem.Message

    $actStopwatch.stop()
    [decimal]$elapsedSecods = $actStopwatch.Elapsed.TotalMinutes
    $actTotalTime = "{0:N2}" -f $elapsedSecods

    throw $("[$($afItems.itemName)] errMsg($($errMsg)) errLn($($errLine)) duration($($actTotalTime))")
}

This now produces nice output like I wanted:

and the Orchestration output as:

I have 2 slight problems still however.

It appears that for some or other reason (I am struggling to find why), every now and again the orchestrator will appear to simply stop. The status will remain as "Running" but there will be no activity in the logs, or any movement on the orchestration itself. If I request a new orchestration it will create it and that might complete as expected again, but the one in "Running" status will just stay like that, eventually causing issue 2.
At some point (I've reduced the timeout values to make it happen quicker), the function will timeout.

When Timing out it does one of several things:

The orchestrator seems to crash out and seems to not recover for that specific orchestration quickly.

Restarting the function at first appears to do nothing, as in it doesn't resume/retry immediately but eventually the orchestration times out again so causing a loop in behaviour. Increasing the functionTimeout in the host.json seems to allow it to eventually complete, but the total duration is then exacerbated:

I get a non-deterministic workflow error with no orchestration output and restart the entire orchestration (with fingers crossed). I believe this is because something has gone wrong in the orchestrator itself as it does not know how to deal with the above timeouts. I've tried playing with the timeout timer but for the life of me again I cannot get this to work when using fan-out/fan-in patterns.

So, my question is simple. Considering the orchestrator now appropriately handles failures etc in activities, how can I apply appropriate error handling to the orchestrator itself, especially in the fan-in/fan-out pattern? I don't want to set the functionTimeout setting to indefinite as it is valid that some of my activities might time out from time to time, so would need to deal with these. Also below becomes a slight issue as a result too.

I've pushed some limits locally a bit in that I create 200 activities and it seems to play nice (mostly). On occasion there will be 1 or 2 activities which never returns (even though they are meant to simply return a duration in my code examples above) and the orchestrator repeats the above behaviour to some degree.

I can only assume it struggles to collate all the activities in this case which then causes the orchestrator to run waaaay longer than expected (even though all activities completed) After a while it (orchestrator function) eventually times out based on the functionTimeout value.

This got me wondering does the "functionTimeout" setting in the host.json apply to everything, including orchestrators? So to test that I set the functionTimeout to a low value (like 2 minutes) and just start the function (no pending/scheduled/running orchestrations/activities), and true as gold, after 2 minutes it tanks. As some orchestrators might be running for a while this is not ideal, as how do we then accurately set timeouts on activities (which leads back to my question how to do it using the durable timer instead). I am also yet to see what it does when deployed to Azure and actually scales out instances, but that is something for another time. I think the above timeout issue is a problem however so hoping you can point me in the right direction here to at least deal with that (or any unhandled exceptions in the orchestrator itself) first. Thanks for your support though, I think the new SDK is far better than it was previously!

davidmrdavid commented 1 year ago

Thanks for the detailed analysis (this is the kind of feedback we need while the SDK is in preview), @ruankr. Glad to hear we got the output formatted as expected.

The core issue you seem to be experiencing is that the orchestrator is getting stuck in the Running status. From there, the orchestrator may time out which leads to a series of downstream effects, but from what I gather your orchestrator should not timeout in the first place so, for simplicity, I'll focus on tackling that issue first.

So when you said:

"[...] It appears that for some or other reason (I am struggling to find why), every now and again the orchestrator will appear to simply stop. The status will remain as "Running" but there will be no activity in the logs, or any movement on the orchestration itself. "

Is this behavior something you're seeing locally with the latest code samples you shared. If so, I'll try to reproduce this on my end. How many times do you usually have to trigger the orchestrator before you hit this bug? Also, do you trigger orchestrators one at a time (waiting for the previous invocations to complete), or are you triggering them as fast as possible and simultaneously?

Also, when you said:

"[...] So, my question is simple. Considering the orchestrator now appropriately handles failures etc in activities, how can I apply appropriate error handling to the orchestrator itself, especially in the fan-in/fan-out pattern? I don't want to set the functionTimeout setting to indefinite as it is valid that some of my activities might time out from time to time, [...]."

To answer this question, I need to understand what exactly is getting stuck in your local repro. In your local reproducer, are you certain that the problem is that the activities are not completing? My hunch would be that it's more likely that the activities are completing successfully but that the orchestrator is somehow failing to acknowledge their completion and therefore getting stuck. Just curious to know if, when looking at your terminal logs, you're able to confirm whether all activities executed despite the fact that the orchestrator is not completing. Please let me know!

ruankrTs commented 1 year ago

@davidmrdavid Thanks for the quick response. This will be another lengthy one I'm afraid hope you don't mind...

In response to your first questions. I've not seen that exact behaviour locally....until now. I want to give context first, and then I will get to the local bit after.

So I have a function that sits in Azure and actually does work when some messages comes in from a schedule (4 times per day). On each schedule the orchestrator receives about 4 messages which are handled and orchestrated independently. 3 of those orchestrations runs 1 activity only, whereas the 4th could be any number of activities but at the moment that number sits at 35.

So here is the activity for this specific function over the last few days:

As you can see for most part it runs without any issues. But then all of a sudden, for some reason, it doesn’t. The failed run above failed with this error:

Orchestrator function 'of-first-orchestrator’ failed: Exception calling "Add" with "2" argument(s): "Item has already been added. Key in dictionary: 'n' Key being added: 'n'".

All the activities actually completed their workloads, but the orchestrator marked 7 of them as timed out, so perhaps your hunch is correct:

Each with this exception:

{
   "$type": "Microsoft.Azure.WebJobs.Host.FunctionTimeoutException, Microsoft.Azure.WebJobs.Host",
   "Timeout": "03:00:00",
   "InstanceId": "abe22068-e199-4075-9fcd-9d2bfa1ee58d",
   "MethodName": "Functions.af-devops-tasks",
   "Handled": false,
   "ClassName": "Microsoft.Azure.WebJobs.Host.FunctionTimeoutException",
   "Message": "Timeout value of 03:00:00 was exceeded by function: Functions.af-devops-tasks",
   "Data": null,
   "InnerException": null,
   "HelpURL": null,
   "StackTraceString": "   at Microsoft.Azure.WebJobs.Host.Executors.FunctionExecutor.TryHandleTimeoutAsync(Task invokeTask, CancellationToken shutdownToken, Boolean throwOnTimeout, CancellationToken timeoutToken, TimeSpan timeoutInterval, IFunctionInstance instance, Action onTimeout) in D:\\a\\_work\\1\\s\\src\\Microsoft.Azure.WebJobs.Host\\Executors\\FunctionExecutor.cs:line 663\n   at Microsoft.Azure.WebJobs.Host.Executors.FunctionExecutor.InvokeWithTimeoutAsync(IFunctionInvoker invoker, ParameterHelper parameterHelper, CancellationTokenSource timeoutTokenSource, CancellationTokenSource functionCancellationTokenSource, Boolean throwOnTimeout, TimeSpan timerInterval, IFunctionInstance instance) in D:\\a\\_work\\1\\s\\src\\Microsoft.Azure.WebJobs.Host\\Executors\\FunctionExecutor.cs:line 571\n   at Microsoft.Azure.WebJobs.Host.Executors.FunctionExecutor.ExecuteWithWatchersAsync(IFunctionInstanceEx instance, ParameterHelper parameterHelper, ILogger logger, CancellationTokenSource functionCancellationTokenSource) in D:\\a\\_work\\1\\s\\src\\Microsoft.Azure.WebJobs.Host\\Executors\\FunctionExecutor.cs:line 527\n   at Microsoft.Azure.WebJobs.Host.Executors.FunctionExecutor.ExecuteWithLoggingAsync(IFunctionInstanceEx instance, FunctionStartedMessage message, FunctionInstanceLogEntry instanceLogEntry, ParameterHelper parameterHelper, ILogger logger, CancellationToken cancellationToken) in D:\\a\\_work\\1\\s\\src\\Microsoft.Azure.WebJobs.Host\\Executors\\FunctionExecutor.cs:line 306\n   at Microsoft.Azure.WebJobs.Host.Executors.FunctionExecutor.ExecuteWithLoggingAsync(IFunctionInstanceEx instance, FunctionStartedMessage message, FunctionInstanceLogEntry instanceLogEntry, ParameterHelper parameterHelper, ILogger logger, CancellationToken cancellationToken) in D:\\a\\_work\\1\\s\\src\\Microsoft.Azure.WebJobs.Host\\Executors\\FunctionExecutor.cs:line 352\n   at Microsoft.Azure.WebJobs.Host.Executors.FunctionExecutor.TryExecuteAsync(IFunctionInstance functionInstance, CancellationToken cancellationToken) in D:\\a\\_work\\1\\s\\src\\Microsoft.Azure.WebJobs.Host\\Executors\\FunctionExecutor.cs:line 108",
   "RemoteStackTraceString": null,
   "RemoteStackIndex": 0,
   "ExceptionMethod": null,
   "HResult": -2146233088,
   "Source": "Microsoft.Azure.WebJobs.Host",
   "WatsonBuckets": null
}

So interestingly from the above you will notice that all the failed activities have the same timestamp, yet the activities actually succeeded with their tasks. So for some reason the orchestrator did not collect their results and therefore timed out, and because the timeout is not handled, failed.

Similarly, if you look at the run at “2023-08-22T10:04:39Z” that took 3h1m, yet:

And yet my activity here reported a quick turn around itself:

So to me too it seems that it’s something strange with the orchestrator function as it seems to sometimes not collect the results in time, or takes ages to do so, and in that event decides to timeout.

Here is a another example of where it just sticks in the “Running” state:

4 orchestrations are requested more or less the same time, 2 complete and 2 get stuck. All of these normally run for only a few seconds so its not activities taking longer than expected. If I investigate one of the jobs I can see it’s actually not even reported a start yet:

So back to the local: As mentioned I have previously not seen this “stuck in Running” behaviour locally so was busy setting up another test function so I can deploy it to azure and see if I can replicate the behaviour with that instead (as this functions code barely does anything I could easily aggravate its use to try force the issue, and be able to share more logs etc), but before I even got that far it actually happened locally for me, on the second test run. Immediate observation:

As you can see it’s stuck in running. Fortunately I have the debug logs locally and noticed this (vscode buffer didn't allow for everything) :

d5eae: Function 'of-test-orchestrator (Orchestrator)' awaited. IsReplay: False. State: Awaited. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.2. SequenceNumber: 522.
[2023-08-23T09:17:40.751Z] INFORMATION: test-item-106 completed in [0.38]
[2023-08-23T09:17:40.752Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Function 'af-test-activity1 (Activity)' completed. ContinuedAsNew: False. IsReplay: False. Output: (168 bytes). State: Completed. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.2. SequenceNumber: 523. TaskEventId: 144
[2023-08-23T09:17:40.944Z] INFORMATION: test-item-107 completed in [0.55]
[2023-08-23T09:17:40.946Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Function 'af-test-activity1 (Activity)' completed. ContinuedAsNew: False. IsReplay: False. Output: (168 bytes). State: Completed. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.2. SequenceNumber: 524. TaskEventId: 134
[2023-08-23T09:17:41.109Z] INFORMATION: profile load completed
[2023-08-23T09:17:41.109Z] INFORMATION: connected function to azure using spn
[2023-08-23T09:17:41.219Z] INFORMATION: test-item-39 completed in [0.73]
[2023-08-23T09:17:41.219Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Function 'af-test-activity1 (Activity)' completed. ContinuedAsNew: False. IsReplay: False. Output: (164 bytes). State: Completed. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.2. SequenceNumber: 525. TaskEventId: 86
[2023-08-23T09:17:41.231Z] INFORMATION: test-item-193 completed in [0.40]
[2023-08-23T09:17:41.232Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Function 'af-test-activity1 (Activity)' completed. ContinuedAsNew: False. IsReplay: False. Output: (168 bytes). State: Completed. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.2. SequenceNumber: 526. TaskEventId: 145
[2023-08-23T09:17:42.059Z] INFORMATION: test-item-141 completed in [0.38]
[2023-08-23T09:17:42.059Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Function 'af-test-activity1 (Activity)' completed. ContinuedAsNew: False. IsReplay: False. Output: (168 bytes). State: Completed. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.2. SequenceNumber: 527. TaskEventId: 71
[2023-08-23T09:17:42.659Z] INFORMATION: connected function to azure using spn
[2023-08-23T09:17:42.659Z] INFORMATION: profile load completed
[2023-08-23T09:17:42.837Z] INFORMATION: test-item-4 completed in [0.58]
[2023-08-23T09:17:42.838Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Function 'af-test-activity1 (Activity)' completed. ContinuedAsNew: False. IsReplay: False. Output: (160 bytes). State: Completed. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.2. SequenceNumber: 528. TaskEventId: 135
[2023-08-23T09:17:43.046Z] INFORMATION: test-item-132 completed in [0.42]
[2023-08-23T09:17:43.046Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Function 'af-test-activity1 (Activity)' completed. ContinuedAsNew: False. IsReplay: False. Output: (168 bytes). State: Completed. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.2. SequenceNumber: 529. TaskEventId: 164
[2023-08-23T09:17:43.806Z] INFORMATION: profile load completed
[2023-08-23T09:17:43.806Z] INFORMATION: connected function to azure using spn
[2023-08-23T09:17:44.414Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Function 'af-test-activity1 (Activity)' completed. ContinuedAsNew: False. IsReplay: False. Output: (164 bytes). State: Completed. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.2. SequenceNumber: 530. TaskEventId: 75
[2023-08-23T09:17:45.140Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Function 'of-test-orchestrator (Orchestrator)' awaited. IsReplay: False. State: Awaited. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.2. SequenceNumber: 531.
[2023-08-23T09:17:45.298Z] INFORMATION: test-item-151 completed in [0.28]
[2023-08-23T09:17:45.298Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Function 'af-test-activity1 (Activity)' completed. ContinuedAsNew: False. IsReplay: False. Output: (168 bytes). State: Completed. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.2. SequenceNumber: 532. TaskEventId: 57
[2023-08-23T09:17:45.484Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Function 'of-test-orchestrator (Orchestrator)' awaited. IsReplay: False. State: Awaited. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.2. SequenceNumber: 533.
[2023-08-23T09:17:45.488Z] INFORMATION: test-item-12 completed in [0.52]
[2023-08-23T09:17:45.489Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Function 'af-test-activity1 (Activity)' completed. ContinuedAsNew: False. IsReplay: False. Output: (164 bytes). State: Completed. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.2. SequenceNumber: 534. TaskEventId: 155
[2023-08-23T09:17:45.912Z] INFORMATION: test-item-76 completed in [0.77]
[2023-08-23T09:17:45.912Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Function 'af-test-activity1 (Activity)' completed. ContinuedAsNew: False. IsReplay: False. Output: (164 bytes). State: Completed. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.2. SequenceNumber: 535. TaskEventId: 156
[2023-08-23T09:17:46.172Z] INFORMATION: test-item-177 completed in [0.85]
[2023-08-23T09:17:46.172Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Function 'af-test-activity1 (Activity)' completed. ContinuedAsNew: False. IsReplay: False. Output: (168 bytes). State: Completed. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.2. SequenceNumber: 536. TaskEventId: 99
[2023-08-23T09:17:46.177Z] INFORMATION: test-item-74 completed in [0.70]
[2023-08-23T09:17:46.178Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Function 'af-test-activity1 (Activity)' completed. ContinuedAsNew: False. IsReplay: False. Output: (164 bytes). State: Completed. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.2. SequenceNumber: 537. TaskEventId: 61
[2023-08-23T09:17:46.347Z] INFORMATION: test-item-182 completed in [0.95]
[2023-08-23T09:17:46.348Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Function 'af-test-activity1 (Activity)' completed. ContinuedAsNew: False. IsReplay: False. Output: (168 bytes). State: Completed. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.2. SequenceNumber: 538. TaskEventId: 90
[2023-08-23T09:17:46.674Z] INFORMATION: test-item-19 completed in [0.57]
[2023-08-23T09:17:46.674Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Function 'af-test-activity1 (Activity)' completed. ContinuedAsNew: False. IsReplay: False. Output: (164 bytes). State: Completed. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.2. SequenceNumber: 539. TaskEventId: 55
[2023-08-23T09:17:46.816Z] INFORMATION: test-item-175 completed in [0.45]
[2023-08-23T09:17:46.816Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Function 'af-test-activity1 (Activity)' completed. ContinuedAsNew: False. IsReplay: False. Output: (168 bytes). State: Completed. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.2. SequenceNumber: 540. TaskEventId: 68
[2023-08-23T09:17:47.151Z] INFORMATION: test-item-180 completed in [0.98]
[2023-08-23T09:17:47.152Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Function 'af-test-activity1 (Activity)' completed. ContinuedAsNew: False. IsReplay: False. Output: (168 bytes). State: Completed. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.2. SequenceNumber: 541. TaskEventId: 104
[2023-08-23T09:17:47.747Z] INFORMATION: test-item-179 completed in [0.37]
[2023-08-23T09:17:47.747Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Function 'af-test-activity1 (Activity)' completed. ContinuedAsNew: False. IsReplay: False. Output: (168 bytes). State: Completed. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.2. SequenceNumber: 542. TaskEventId: 173
[2023-08-23T09:17:47.815Z] INFORMATION: test-item-118 completed in [0.17]
[2023-08-23T09:17:47.815Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Function 'af-test-activity1 (Activity)' completed. ContinuedAsNew: False. IsReplay: False. Output: (168 bytes). State: Completed. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.2. SequenceNumber: 543. TaskEventId: 192
[2023-08-23T09:17:47.912Z] INFORMATION: test-item-15 completed in [0.80]
[2023-08-23T09:17:47.912Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Function 'af-test-activity1 (Activity)' completed. ContinuedAsNew: False. IsReplay: False. Output: (164 bytes). State: Completed. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.2. SequenceNumber: 544. TaskEventId: 88
[2023-08-23T09:17:48.003Z] INFORMATION: test-item-61 completed in [0.63]
[2023-08-23T09:17:48.003Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Function 'af-test-activity1 (Activity)' completed. ContinuedAsNew: False. IsReplay: False. Output: (164 bytes). State: Completed. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.2. SequenceNumber: 545. TaskEventId: 136
[2023-08-23T09:17:49.206Z] INFORMATION: test-item-6 completed in [0.60]
[2023-08-23T09:17:49.206Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Function 'af-test-activity1 (Activity)' completed. ContinuedAsNew: False. IsReplay: False. Output: (160 bytes). State: Completed. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.2. SequenceNumber: 546. TaskEventId: 141
[2023-08-23T09:17:50.054Z] INFORMATION: test-item-197 completed in [0.28]
[2023-08-23T09:17:50.055Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Function 'af-test-activity1 (Activity)' completed. ContinuedAsNew: False. IsReplay: False. Output: (168 bytes). State: Completed. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.2. SequenceNumber: 547. TaskEventId: 188
[2023-08-23T09:17:51.004Z] INFORMATION: test-item-31 completed in [0.68]
[2023-08-23T09:17:51.004Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Function 'af-test-activity1 (Activity)' completed. ContinuedAsNew: False. IsReplay: False. Output: (164 bytes). State: Completed. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.2. SequenceNumber: 548. TaskEventId: 153
[2023-08-23T09:17:51.237Z] INFORMATION: test-item-25 completed in [0.52]
[2023-08-23T09:17:51.237Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Function 'af-test-activity1 (Activity)' completed. ContinuedAsNew: False. IsReplay: False. Output: (164 bytes). State: Completed. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.2. SequenceNumber: 549. TaskEventId: 163
[2023-08-23T09:17:52.224Z] INFORMATION: test-item-116 completed in [0.97]
[2023-08-23T09:17:52.224Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Function 'af-test-activity1 (Activity)' completed. ContinuedAsNew: False. IsReplay: False. Output: (168 bytes). State: Completed. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.2. SequenceNumber: 550. TaskEventId: 131
[2023-08-23T09:17:52.550Z] INFORMATION: test-item-186 completed in [0.47]
[2023-08-23T09:17:52.550Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Function 'af-test-activity1 (Activity)' completed. ContinuedAsNew: False. IsReplay: False. Output: (168 bytes). State: Completed. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.2. SequenceNumber: 551. TaskEventId: 160
[2023-08-23T09:17:52.610Z] INFORMATION: test-item-194 completed in [0.27]
[2023-08-23T09:17:52.610Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Function 'af-test-activity1 (Activity)' completed. ContinuedAsNew: False. IsReplay: False. Output: (168 bytes). State: Completed. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.2. SequenceNumber: 552. TaskEventId: 130
[2023-08-23T09:17:53.609Z] INFORMATION: test-item-172 completed in [0.28]
[2023-08-23T09:17:53.609Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Function 'af-test-activity1 (Activity)' completed. ContinuedAsNew: False. IsReplay: False. Output: (168 bytes). State: Completed. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.2. SequenceNumber: 553. TaskEventId: 170
[2023-08-23T09:17:54.299Z] INFORMATION: test-item-75 completed in [0.43]
[2023-08-23T09:17:54.299Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Function 'af-test-activity1 (Activity)' completed. ContinuedAsNew: False. IsReplay: False. Output: (164 bytes). State: Completed. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.2. SequenceNumber: 554. TaskEventId: 142
[2023-08-23T09:17:54.659Z] INFORMATION: test-item-95 completed in [0.32]
[2023-08-23T09:17:54.659Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Function 'af-test-activity1 (Activity)' completed. ContinuedAsNew: False. IsReplay: False. Output: (164 bytes). State: Completed. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.2. SequenceNumber: 555. TaskEventId: 154
[2023-08-23T09:17:54.660Z] INFORMATION: test-item-62 completed in [0.32]
[2023-08-23T09:17:54.660Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Function 'af-test-activity1 (Activity)' completed. ContinuedAsNew: False. IsReplay: False. Output: (164 bytes). State: Completed. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.2. SequenceNumber: 556. TaskEventId: 189
[2023-08-23T09:17:55.078Z] INFORMATION: test-item-156 completed in [0.48]
[2023-08-23T09:17:55.078Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Function 'af-test-activity1 (Activity)' completed. ContinuedAsNew: False. IsReplay: False. Output: (168 bytes). State: Completed. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.2. SequenceNumber: 557. TaskEventId: 168
[2023-08-23T09:17:55.672Z] INFORMATION: test-item-165 completed in [0.22]
[2023-08-23T09:17:55.672Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Function 'af-test-activity1 (Activity)' completed. ContinuedAsNew: False. IsReplay: False. Output: (168 bytes). State: Completed. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.2. SequenceNumber: 558. TaskEventId: 191
[2023-08-23T09:17:55.810Z] INFORMATION: test-item-195 completed in [0.20]
[2023-08-23T09:17:55.811Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Function 'af-test-activity1 (Activity)' completed. ContinuedAsNew: False. IsReplay: False. Output: (168 bytes). State: Completed. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.2. SequenceNumber: 559. TaskEventId: 177
[2023-08-23T09:17:56.046Z] INFORMATION: test-item-191 completed in [0.58]
[2023-08-23T09:17:56.047Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Function 'af-test-activity1 (Activity)' completed. ContinuedAsNew: False. IsReplay: False. Output: (168 bytes). State: Completed. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.2. SequenceNumber: 560. TaskEventId: 178
[2023-08-23T09:17:56.055Z] INFORMATION: test-item-27 completed in [0.38]
[2023-08-23T09:17:56.055Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Function 'af-test-activity1 (Activity)' completed. ContinuedAsNew: False. IsReplay: False. Output: (164 bytes). State: Completed. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.2. SequenceNumber: 561. TaskEventId: 181
[2023-08-23T09:17:56.170Z] INFORMATION: test-item-192 completed in [0.92]
[2023-08-23T09:17:56.170Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Function 'af-test-activity1 (Activity)' completed. ContinuedAsNew: False. IsReplay: False. Output: (168 bytes). State: Completed. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.2. SequenceNumber: 562. TaskEventId: 87
[2023-08-23T09:17:56.176Z] INFORMATION: test-item-82 completed in [0.87]
[2023-08-23T09:17:56.177Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Function 'af-test-activity1 (Activity)' completed. ContinuedAsNew: False. IsReplay: False. Output: (164 bytes). State: Completed. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.2. SequenceNumber: 563. TaskEventId: 80
[2023-08-23T09:17:57.176Z] INFORMATION: test-item-70 completed in [0.88]
[2023-08-23T09:17:57.177Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Function 'af-test-activity1 (Activity)' completed. ContinuedAsNew: False. IsReplay: False. Output: (164 bytes). State: Completed. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.2. SequenceNumber: 564. TaskEventId: 149
[2023-08-23T09:17:58.807Z] INFORMATION: test-item-143 completed in [0.35]
[2023-08-23T09:17:58.807Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Function 'af-test-activity1 (Activity)' completed. ContinuedAsNew: False. IsReplay: False. Output: (168 bytes). State: Completed. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.2. SequenceNumber: 565. TaskEventId: 190
[2023-08-23T09:18:00.488Z] INFORMATION: test-item-80 completed in [0.77]
[2023-08-23T09:18:00.489Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Function 'af-test-activity1 (Activity)' completed. ContinuedAsNew: False. IsReplay: False. Output: (164 bytes). State: Completed. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.2. SequenceNumber: 566. TaskEventId: 162
[2023-08-23T09:18:00.837Z] INFORMATION: test-item-199 completed in [0.88]
[2023-08-23T09:18:00.838Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Function 'af-test-activity1 (Activity)' completed. ContinuedAsNew: False. IsReplay: False. Output: (168 bytes). State: Completed. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.2. SequenceNumber: 567. TaskEventId: 126
[2023-08-23T09:18:00.917Z] INFORMATION: test-item-111 completed in [0.77]
[2023-08-23T09:18:00.917Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Function 'af-test-activity1 (Activity)' completed. ContinuedAsNew: False. IsReplay: False. Output: (168 bytes). State: Completed. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.2. SequenceNumber: 568. TaskEventId: 161
[2023-08-23T09:18:01.063Z] INFORMATION: test-item-154 completed in [0.55]
[2023-08-23T09:18:01.063Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Function 'af-test-activity1 (Activity)' completed. ContinuedAsNew: False. IsReplay: False. Output: (168 bytes). State: Completed. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.2. SequenceNumber: 569. TaskEventId: 137
[2023-08-23T09:18:01.355Z] INFORMATION: test-item-89 completed in [0.93]
[2023-08-23T09:18:01.356Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Function 'af-test-activity1 (Activity)' completed. ContinuedAsNew: False. IsReplay: False. Output: (164 bytes). State: Completed. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.2. SequenceNumber: 570. TaskEventId: 67
[2023-08-23T09:18:01.810Z] INFORMATION: test-item-140 completed in [0.30]
[2023-08-23T09:18:01.810Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Function 'af-test-activity1 (Activity)' completed. ContinuedAsNew: False. IsReplay: False. Output: (168 bytes). State: Completed. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.2. SequenceNumber: 571. TaskEventId: 45
[2023-08-23T09:18:01.909Z] INFORMATION: test-item-183 completed in [0.52]
[2023-08-23T09:18:01.910Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Function 'af-test-activity1 (Activity)' completed. ContinuedAsNew: False. IsReplay: False. Output: (168 bytes). State: Completed. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.2. SequenceNumber: 572. TaskEventId: 159
[2023-08-23T09:18:02.115Z] INFORMATION: test-item-17 completed in [0.35]
[2023-08-23T09:18:02.116Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Function 'af-test-activity1 (Activity)' completed. ContinuedAsNew: False. IsReplay: False. Output: (164 bytes). State: Completed. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.2. SequenceNumber: 573. TaskEventId: 196
[2023-08-23T09:18:04.355Z] INFORMATION: test-item-101 completed in [0.98]
[2023-08-23T09:18:04.355Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Function 'af-test-activity1 (Activity)' completed. ContinuedAsNew: False. IsReplay: False. Output: (168 bytes). State: Completed. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.2. SequenceNumber: 574. TaskEventId: 72
[2023-08-23T09:18:04.756Z] INFORMATION: test-item-157 completed in [0.68]
[2023-08-23T09:18:04.756Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Function 'af-test-activity1 (Activity)' completed. ContinuedAsNew: False. IsReplay: False. Output: (168 bytes). State: Completed. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.2. SequenceNumber: 575. TaskEventId: 140
[2023-08-23T09:18:04.816Z] INFORMATION: test-item-88 completed in [0.75]
[2023-08-23T09:18:04.816Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Function 'af-test-activity1 (Activity)' completed. ContinuedAsNew: False. IsReplay: False. Output: (164 bytes). State: Completed. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.2. SequenceNumber: 576. TaskEventId: 174
[2023-08-23T09:18:05.173Z] INFORMATION: test-item-20 completed in [0.83]
[2023-08-23T09:18:05.174Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Function 'af-test-activity1 (Activity)' completed. ContinuedAsNew: False. IsReplay: False. Output: (164 bytes). State: Completed. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.2. SequenceNumber: 577. TaskEventId: 65
[2023-08-23T09:18:05.506Z] INFORMATION: test-item-35 completed in [0.55]
[2023-08-23T09:18:05.506Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Function 'af-test-activity1 (Activity)' completed. ContinuedAsNew: False. IsReplay: False. Output: (164 bytes). State: Completed. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.2. SequenceNumber: 578. TaskEventId: 185
[2023-08-23T09:18:06.063Z] INFORMATION: test-item-167 completed in [0.63]
[2023-08-23T09:18:06.063Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Function 'af-test-activity1 (Activity)' completed. ContinuedAsNew: False. IsReplay: False. Output: (168 bytes). State: Completed. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.2. SequenceNumber: 579. TaskEventId: 169
[2023-08-23T09:18:06.674Z] INFORMATION: test-item-160 completed in [0.90]
[2023-08-23T09:18:06.674Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Function 'af-test-activity1 (Activity)' completed. ContinuedAsNew: False. IsReplay: False. Output: (168 bytes). State: Completed. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.2. SequenceNumber: 580. TaskEventId: 138
[2023-08-23T09:18:07.420Z] INFORMATION: test-item-138 completed in [0.62]
[2023-08-23T09:18:07.420Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Function 'af-test-activity1 (Activity)' completed. ContinuedAsNew: False. IsReplay: False. Output: (168 bytes). State: Completed. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.2. SequenceNumber: 581. TaskEventId: 148
[2023-08-23T09:18:07.808Z] INFORMATION: test-item-152 completed in [0.50]
[2023-08-23T09:18:07.808Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Function 'af-test-activity1 (Activity)' completed. ContinuedAsNew: False. IsReplay: False. Output: (168 bytes). State: Completed. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.2. SequenceNumber: 582. TaskEventId: 143
[2023-08-23T09:18:07.970Z] INFORMATION: test-item-190 completed in [0.95]
[2023-08-23T09:18:07.971Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Function 'af-test-activity1 (Activity)' completed. ContinuedAsNew: False. IsReplay: False. Output: (168 bytes). State: Completed. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.2. SequenceNumber: 583. TaskEventId: 146
[2023-08-23T09:18:08.673Z] INFORMATION: test-item-112 completed in [0.93]
[2023-08-23T09:18:08.673Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Function 'af-test-activity1 (Activity)' completed. ContinuedAsNew: False. IsReplay: False. Output: (168 bytes). State: Completed. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.2. SequenceNumber: 584. TaskEventId: 151
[2023-08-23T09:18:10.373Z] INFORMATION: test-item-134 completed in [0.52]
[2023-08-23T09:18:10.373Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Function 'af-test-activity1 (Activity)' completed. ContinuedAsNew: False. IsReplay: False. Output: (168 bytes). State: Completed. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.2. SequenceNumber: 585. TaskEventId: 194
[2023-08-23T09:18:11.231Z] INFORMATION: test-item-72 completed in [0.90]
[2023-08-23T09:18:11.231Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Function 'af-test-activity1 (Activity)' completed. ContinuedAsNew: False. IsReplay: False. Output: (164 bytes). State: Completed. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.2. SequenceNumber: 586. TaskEventId: 165
[2023-08-23T09:18:11.674Z] INFORMATION: test-item-99 completed in [0.48]
[2023-08-23T09:18:11.674Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Function 'af-test-activity1 (Activity)' completed. ContinuedAsNew: False. IsReplay: False. Output: (164 bytes). State: Completed. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.2. SequenceNumber: 587. TaskEventId: 100
[2023-08-23T09:18:11.807Z] INFORMATION: test-item-56 completed in [0.57]
[2023-08-23T09:18:11.807Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Function 'af-test-activity1 (Activity)' completed. ContinuedAsNew: False. IsReplay: False. Output: (164 bytes). State: Completed. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.2. SequenceNumber: 588. TaskEventId: 197
[2023-08-23T09:18:12.420Z] INFORMATION: test-item-44 completed in [0.70]
[2023-08-23T09:18:12.420Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Function 'af-test-activity1 (Activity)' completed. ContinuedAsNew: False. IsReplay: False. Output: (164 bytes). State: Completed. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.2. SequenceNumber: 589. TaskEventId: 186
[2023-08-23T09:18:12.755Z] INFORMATION: test-item-129 completed in [0.82]
[2023-08-23T09:18:12.755Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Function 'af-test-activity1 (Activity)' completed. ContinuedAsNew: False. IsReplay: False. Output: (168 bytes). State: Completed. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.2. SequenceNumber: 590. TaskEventId: 182
[2023-08-23T09:18:13.116Z] INFORMATION: test-item-144 completed in [0.53]
[2023-08-23T09:18:13.117Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Function 'af-test-activity1 (Activity)' completed. ContinuedAsNew: False. IsReplay: False. Output: (168 bytes). State: Completed. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.2. SequenceNumber: 591. TaskEventId: 157
[2023-08-23T09:18:13.297Z] INFORMATION: test-item-46 completed in [0.93]
[2023-08-23T09:18:13.297Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Function 'af-test-activity1 (Activity)' completed. ContinuedAsNew: False. IsReplay: False. Output: (164 bytes). State: Completed. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.2. SequenceNumber: 592. TaskEventId: 167
[2023-08-23T09:18:13.673Z] INFORMATION: test-item-200 completed in [0.52]
[2023-08-23T09:18:13.673Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Function 'af-test-activity1 (Activity)' completed. ContinuedAsNew: False. IsReplay: False. Output: (168 bytes). State: Completed. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.2. SequenceNumber: 593. TaskEventId: 180
[2023-08-23T09:18:14.747Z] INFORMATION: test-item-51 completed in [0.82]
[2023-08-23T09:18:14.747Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Function 'af-test-activity1 (Activity)' completed. ContinuedAsNew: False. IsReplay: False. Output: (164 bytes). State: Completed. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.2. SequenceNumber: 594. TaskEventId: 172
[2023-08-23T09:18:16.063Z] INFORMATION: test-item-13 completed in [0.80]
[2023-08-23T09:18:16.063Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Function 'af-test-activity1 (Activity)' completed. ContinuedAsNew: False. IsReplay: False. Output: (164 bytes). State: Completed. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.2. SequenceNumber: 595. TaskEventId: 166
[2023-08-23T09:18:16.755Z] INFORMATION: test-item-49 completed in [0.88]
[2023-08-23T09:18:16.755Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Function 'af-test-activity1 (Activity)' completed. ContinuedAsNew: False. IsReplay: False. Output: (164 bytes). State: Completed. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.2. SequenceNumber: 596. TaskEventId: 183
[2023-08-23T09:18:16.811Z] INFORMATION: test-item-42 completed in [0.55]
[2023-08-23T09:18:16.811Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Function 'af-test-activity1 (Activity)' completed. ContinuedAsNew: False. IsReplay: False. Output: (164 bytes). State: Completed. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.2. SequenceNumber: 597. TaskEventId: 171
[2023-08-23T09:18:17.115Z] INFORMATION: test-item-149 completed in [0.60]
[2023-08-23T09:18:17.115Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Function 'af-test-activity1 (Activity)' completed. ContinuedAsNew: False. IsReplay: False. Output: (168 bytes). State: Completed. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.2. SequenceNumber: 598. TaskEventId: 199
[2023-08-23T09:18:17.810Z] INFORMATION: test-item-126 completed in [0.67]
[2023-08-23T09:18:17.810Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Function 'af-test-activity1 (Activity)' completed. ContinuedAsNew: False. IsReplay: False. Output: (168 bytes). State: Completed. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.2. SequenceNumber: 599. TaskEventId: 195
[2023-08-23T09:18:17.904Z] INFORMATION: test-item-86 completed in [0.78]
[2023-08-23T09:18:17.905Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Function 'af-test-activity1 (Activity)' completed. ContinuedAsNew: False. IsReplay: False. Output: (164 bytes). State: Completed. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.2. SequenceNumber: 600. TaskEventId: 175
[2023-08-23T09:18:19.660Z] INFORMATION: test-item-83 completed in [0.73]
[2023-08-23T09:18:19.660Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Function 'af-test-activity1 (Activity)' completed. ContinuedAsNew: False. IsReplay: False. Output: (164 bytes). State: Completed. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.2. SequenceNumber: 601. TaskEventId: 179
[2023-08-23T09:18:23.673Z] INFORMATION: test-item-94 completed in [0.68]
[2023-08-23T09:18:23.674Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Function 'af-test-activity1 (Activity)' completed. ContinuedAsNew: False. IsReplay: False. Output: (164 bytes). State: Completed. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.2. SequenceNumber: 602. TaskEventId: 79
[2023-08-23T09:18:25.115Z] INFORMATION: test-item-173 completed in [0.73]
[2023-08-23T09:18:25.116Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Function 'af-test-activity1 (Activity)' completed. ContinuedAsNew: False. IsReplay: False. Output: (168 bytes). State: Completed. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.2. SequenceNumber: 603. TaskEventId: 198
[2023-08-23T09:18:28.421Z] INFORMATION: test-item-47 completed in [0.97]
[2023-08-23T09:18:28.422Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Function 'af-test-activity1 (Activity)' completed. ContinuedAsNew: False. IsReplay: False. Output: (164 bytes). State: Completed. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.2. SequenceNumber: 604. TaskEventId: 158
[2023-08-23T09:18:28.506Z] INFORMATION: test-item-14 completed in [0.93]
[2023-08-23T09:18:28.506Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Function 'af-test-activity1 (Activity)' completed. ContinuedAsNew: False. IsReplay: False. Output: (164 bytes). State: Completed. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.2. SequenceNumber: 605. TaskEventId: 187
[2023-08-23T09:18:29.116Z] INFORMATION: test-item-168 completed in [0.80]
[2023-08-23T09:18:29.116Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Function 'af-test-activity1 (Activity)' completed. ContinuedAsNew: False. IsReplay: False. Output: (168 bytes). State: Completed. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.2. SequenceNumber: 606. TaskEventId: 114
[2023-08-23T09:18:29.811Z] INFORMATION: test-item-120 completed in [0.87]
[2023-08-23T09:18:29.811Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Function 'af-test-activity1 (Activity)' completed. ContinuedAsNew: False. IsReplay: False. Output: (168 bytes). State: Completed. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.2. SequenceNumber: 607. TaskEventId: 193
[2023-08-23T09:18:30.665Z] INFORMATION: test-item-68 completed in [0.92]
[2023-08-23T09:18:30.666Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Function 'af-test-activity1 (Activity)' completed. ContinuedAsNew: False. IsReplay: False. Output: (164 bytes). State: Completed. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.2. SequenceNumber: 608. TaskEventId: 184
[2023-08-23T09:20:23.207Z] INFORMATION: test-item-50 completed in [3.17]
[2023-08-23T09:20:23.207Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Function 'af-test-activity1 (Activity)' completed. ContinuedAsNew: False. IsReplay: False. Output: (164 bytes). State: Completed. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.2. SequenceNumber: 609. TaskEventId: 133
[2023-08-23T09:22:51.154Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Received a duplicate message [TaskCompleted#155] from ldevtest-control-03 with ID = fa2aae8d-945b-44be-b02e-c8732d2f520a and dequeue count = 2
[2023-08-23T09:22:51.155Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Received a duplicate message [TaskCompleted#156] from ldevtest-control-03 with ID = bc118002-9f2f-421a-9b40-f4c30651b6a2 and dequeue count = 2
[2023-08-23T09:22:51.155Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Received a duplicate message [TaskCompleted#61] from ldevtest-control-03 with ID = 48c6de2f-2b23-41ca-bc85-79727520c431 and dequeue count = 2
[2023-08-23T09:22:51.155Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Received a duplicate message [TaskCompleted#99] from ldevtest-control-03 with ID = d2d46983-1339-462b-b5e5-04d32125d4e7 and dequeue count = 2
[2023-08-23T09:22:51.155Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Received a duplicate message [TaskCompleted#90] from ldevtest-control-03 with ID = ecca492d-3754-4c81-8e0e-b672bd6c08e9 and dequeue count = 2
[2023-08-23T09:22:51.155Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Received a duplicate message [TaskCompleted#55] from ldevtest-control-03 with ID = e271ace7-f671-48fb-b1b5-722295233671 and dequeue count = 2
[2023-08-23T09:22:51.155Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Received a duplicate message [TaskCompleted#68] from ldevtest-control-03 with ID = 95f51671-7271-495e-8a98-5d85a700a8b2 and dequeue count = 2
[2023-08-23T09:22:51.155Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Received a duplicate message [TaskCompleted#104] from ldevtest-control-03 with ID = 536e1f80-aafd-446f-ba29-4069545fdbeb and dequeue count = 2
[2023-08-23T09:22:51.155Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Received a duplicate message [TaskCompleted#173] from ldevtest-control-03 with ID = 82a62915-9ac5-4356-bfd0-18a1c55dd41f and dequeue count = 2
[2023-08-23T09:22:51.155Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Received a duplicate message [TaskCompleted#192] from ldevtest-control-03 with ID = ba4c3aff-88e5-4ceb-b51c-d6338a341fb2 and dequeue count = 2
[2023-08-23T09:22:51.155Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Received a duplicate message [TaskCompleted#88] from ldevtest-control-03 with ID = c484c453-3925-49df-817d-790eb0348841 and dequeue count = 2
[2023-08-23T09:22:51.156Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Received a duplicate message [TaskCompleted#136] from ldevtest-control-03 with ID = 40c9ffe4-5ecf-4dba-b7be-6e1a3371a972 and dequeue count = 2
[2023-08-23T09:22:51.156Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Received a duplicate message [TaskCompleted#141] from ldevtest-control-03 with ID = b5a5703d-ae45-4a74-b5e8-80d6fe47096d and dequeue count = 2
[2023-08-23T09:22:51.156Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Received a duplicate message [TaskCompleted#188] from ldevtest-control-03 with ID = 1c483a3f-eef6-4e0a-bfab-ad0c255f03ad and dequeue count = 2
[2023-08-23T09:22:51.156Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Received a duplicate message [TaskCompleted#153] from ldevtest-control-03 with ID = 966b6068-4823-4bbe-911c-8e8fa5e402da and dequeue count = 2
[2023-08-23T09:22:51.374Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Received a duplicate message [TaskCompleted#163] from ldevtest-control-03 with ID = 2a4037d9-da75-4227-83f5-e0d890cd5135 and dequeue count = 2
[2023-08-23T09:22:52.498Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Received a duplicate message [TaskCompleted#131] from ldevtest-control-03 with ID = b6e76489-cacd-4205-9ecb-1b12cc2e14ea and dequeue count = 2
[2023-08-23T09:22:52.580Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Received a duplicate message [TaskCompleted#160] from ldevtest-control-03 with ID = 92b3d5e0-c4f1-4971-9270-0b4f50d021e7 and dequeue count = 2
[2023-08-23T09:22:52.661Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Received a duplicate message [TaskCompleted#130] from ldevtest-control-03 with ID = f3007ffe-db8d-4807-83de-91cf55705605 and dequeue count = 2
[2023-08-23T09:22:53.727Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Received a duplicate message [TaskCompleted#170] from ldevtest-control-03 with ID = 8341e54a-447a-4892-8153-16feb58765ae and dequeue count = 2
[2023-08-23T09:22:54.373Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Received a duplicate message [TaskCompleted#142] from ldevtest-control-03 with ID = 84c47f01-0f65-4994-8888-fbd713acc2ed and dequeue count = 2
[2023-08-23T09:22:54.759Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Received a duplicate message [TaskCompleted#189] from ldevtest-control-03 with ID = a6c80b02-8514-43d1-aa86-29e0e276e493 and dequeue count = 2
[2023-08-23T09:22:54.759Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Received a duplicate message [TaskCompleted#154] from ldevtest-control-03 with ID = e84501f5-a682-4c77-bb54-7be2b4e52289 and dequeue count = 2
[2023-08-23T09:22:55.377Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Received a duplicate message [TaskCompleted#168] from ldevtest-control-03 with ID = 0d964273-55c3-46af-97ac-eb65c891de85 and dequeue count = 2
[2023-08-23T09:22:55.741Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Received a duplicate message [TaskCompleted#191] from ldevtest-control-03 with ID = 3b35e68d-a9c3-407f-8c8b-20d9e0d396ce and dequeue count = 2
[2023-08-23T09:22:55.932Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Received a duplicate message [TaskCompleted#177] from ldevtest-control-03 with ID = 7ac38c7d-1069-42d1-ab09-07ca1e6460a8 and dequeue count = 2
[2023-08-23T09:22:56.136Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Received a duplicate message [TaskCompleted#178] from ldevtest-control-03 with ID = d549446d-68a5-4995-b1a3-08ba86f48e21 and dequeue count = 2
[2023-08-23T09:22:56.137Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Received a duplicate message [TaskCompleted#181] from ldevtest-control-03 with ID = 04d624a6-736d-4ecd-9232-5b08ca28252d and dequeue count = 2
[2023-08-23T09:22:56.229Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Received a duplicate message [TaskCompleted#80] from ldevtest-control-03 with ID = 93c8b5c5-dde6-4229-b21f-498b254a3d81 and dequeue count = 2
[2023-08-23T09:22:56.229Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Received a duplicate message [TaskCompleted#87] from ldevtest-control-03 with ID = f34a10d2-e673-450f-9df7-26dd0309ec7a and dequeue count = 2
[2023-08-23T09:22:57.433Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Received a duplicate message [TaskCompleted#149] from ldevtest-control-03 with ID = b56e21f3-a602-4102-a14e-afead1a57d19 and dequeue count = 2
[2023-08-23T09:22:59.497Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Received a duplicate message [TaskCompleted#190] from ldevtest-control-03 with ID = 703c22e2-002b-43fc-b765-ef3d89e020b8 and dequeue count = 2
[2023-08-23T09:23:00.552Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Received a duplicate message [TaskCompleted#162] from ldevtest-control-03 with ID = 08719538-b7cd-4461-b35a-7e14a052a2e6 and dequeue count = 2
[2023-08-23T09:23:00.924Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Received a duplicate message [TaskCompleted#126] from ldevtest-control-03 with ID = 5ae4eaf6-ced9-4787-8408-2b0d2c117700 and dequeue count = 2
[2023-08-23T09:23:00.946Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Received a duplicate message [TaskCompleted#161] from ldevtest-control-03 with ID = 14794a22-f54c-4147-8288-62baffb6a998 and dequeue count = 2
[2023-08-23T09:23:01.148Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Received a duplicate message [TaskCompleted#137] from ldevtest-control-03 with ID = 9103c81c-8892-4c21-a0b2-0b1e9c5c2f8e and dequeue count = 2
[2023-08-23T09:23:01.395Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Received a duplicate message [TaskCompleted#67] from ldevtest-control-03 with ID = 728e4c0e-8534-40ee-a2bf-3d84b23279fe and dequeue count = 2
[2023-08-23T09:23:02.003Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Received a duplicate message [TaskCompleted#45] from ldevtest-control-03 with ID = 0db92a4c-c4c3-477e-955a-6fbb5013e299 and dequeue count = 2
[2023-08-23T09:23:02.003Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Received a duplicate message [TaskCompleted#159] from ldevtest-control-03 with ID = 991e7b4e-5f69-4cf9-9b14-f899a75c3ccf and dequeue count = 2
[2023-08-23T09:23:02.201Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Received a duplicate message [TaskCompleted#196] from ldevtest-control-03 with ID = 1166b61d-bf91-4238-b913-3019c48fde7f and dequeue count = 2
[2023-08-23T09:23:05.749Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Received a duplicate message [TaskCompleted#72] from ldevtest-control-03 with ID = 57d5cf3a-5632-44c6-b22b-15a549f7c766 and dequeue count = 2
[2023-08-23T09:23:05.749Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Received a duplicate message [TaskCompleted#140] from ldevtest-control-03 with ID = cdea5e7b-d117-46ba-a532-ed2ecf401869 and dequeue count = 2
[2023-08-23T09:23:05.749Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Received a duplicate message [TaskCompleted#174] from ldevtest-control-03 with ID = 04df9b48-e8b5-45bd-b85e-803b8e21e272 and dequeue count = 2
[2023-08-23T09:23:05.749Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Received a duplicate message [TaskCompleted#65] from ldevtest-control-03 with ID = 16c305cd-302b-4f45-9ed6-81a1ae0ec438 and dequeue count = 2
[2023-08-23T09:23:05.750Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Received a duplicate message [TaskCompleted#185] from ldevtest-control-03 with ID = 071df520-8ee2-4b6f-9cf8-6ff55a727a53 and dequeue count = 2
[2023-08-23T09:23:06.167Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Received a duplicate message [TaskCompleted#169] from ldevtest-control-03 with ID = 721dd57c-8604-4ee8-8086-a12365b66e2d and dequeue count = 2
[2023-08-23T09:23:06.767Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Received a duplicate message [TaskCompleted#138] from ldevtest-control-03 with ID = 0575c396-7cf1-4549-846b-f20b414d3af7 and dequeue count = 2
[2023-08-23T09:23:07.951Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Received a duplicate message [TaskCompleted#148] from ldevtest-control-03 with ID = 7c2b0040-2d79-48cd-baf3-dcfd6bbfa0fc and dequeue count = 2
[2023-08-23T09:23:07.952Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Received a duplicate message [TaskCompleted#143] from ldevtest-control-03 with ID = 720b4b14-0e8f-4c6b-a892-9e78970f40c2 and dequeue count = 2
[2023-08-23T09:23:08.038Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Received a duplicate message [TaskCompleted#146] from ldevtest-control-03 with ID = 31461529-a2ca-40c7-84e0-04868a1c7005 and dequeue count = 2
[2023-08-23T09:23:08.730Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Received a duplicate message [TaskCompleted#151] from ldevtest-control-03 with ID = cb09fb00-72d3-496d-90e7-6ba8a8d6b3a6 and dequeue count = 2
[2023-08-23T09:23:10.794Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Received a duplicate message [TaskCompleted#194] from ldevtest-control-03 with ID = b400ad61-1f45-4205-8a0c-ce532758817a and dequeue count = 2
[2023-08-23T09:23:11.464Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Received a duplicate message [TaskCompleted#165] from ldevtest-control-03 with ID = 16f2d66d-6d4f-4c30-9656-71ae22f6dbe2 and dequeue count = 2
[2023-08-23T09:23:11.816Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Received a duplicate message [TaskCompleted#100] from ldevtest-control-03 with ID = 1c62b099-0283-45b3-a80d-31a8307998fe and dequeue count = 2
[2023-08-23T09:23:11.841Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Received a duplicate message [TaskCompleted#197] from ldevtest-control-03 with ID = 1bf7d28e-b90f-4dcd-823c-344c6bf8077c and dequeue count = 2
[2023-08-23T09:23:12.894Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Received a duplicate message [TaskCompleted#186] from ldevtest-control-03 with ID = 0b2af605-32f0-403d-9fc1-cb2fd75de6e5 and dequeue count = 2
[2023-08-23T09:23:12.894Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Received a duplicate message [TaskCompleted#182] from ldevtest-control-03 with ID = 9f214e8b-635e-478e-abe6-b0d27fdcbcbc and dequeue count = 2
[2023-08-23T09:23:13.287Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Received a duplicate message [TaskCompleted#157] from ldevtest-control-03 with ID = 57819374-4d38-41d2-94a7-273ff007bf4b and dequeue count = 2
[2023-08-23T09:23:13.371Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Received a duplicate message [TaskCompleted#167] from ldevtest-control-03 with ID = d645f8c3-0f89-4e22-a0db-2021dc27e5e2 and dequeue count = 2
[2023-08-23T09:23:13.754Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Received a duplicate message [TaskCompleted#180] from ldevtest-control-03 with ID = 9616f5cc-3846-4fcb-bd56-2f2169157af9 and dequeue count = 2
[2023-08-23T09:23:14.863Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Received a duplicate message [TaskCompleted#172] from ldevtest-control-03 with ID = 7727e1b4-6835-4cf5-8d88-12dabe8245f4 and dequeue count = 2
[2023-08-23T09:23:16.900Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Received a duplicate message [TaskCompleted#166] from ldevtest-control-03 with ID = 187df13d-7fa8-491c-a5e0-12c91de14720 and dequeue count = 2
[2023-08-23T09:23:16.900Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Received a duplicate message [TaskCompleted#183] from ldevtest-control-03 with ID = e5d60d1b-9f2f-4270-99db-7bea390ee440 and dequeue count = 2
[2023-08-23T09:23:16.900Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Received a duplicate message [TaskCompleted#171] from ldevtest-control-03 with ID = 299b19d0-ff2a-479f-b3e2-4c849615f6a4 and dequeue count = 2
[2023-08-23T09:23:17.305Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Received a duplicate message [TaskCompleted#199] from ldevtest-control-03 with ID = 598a7b61-7b44-40fb-b5c7-03684a7a293d and dequeue count = 2
[2023-08-23T09:23:17.957Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Received a duplicate message [TaskCompleted#195] from ldevtest-control-03 with ID = ec121e96-a4a5-4e2f-b773-dd0df559f281 and dequeue count = 2
[2023-08-23T09:23:17.957Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Received a duplicate message [TaskCompleted#175] from ldevtest-control-03 with ID = 69b7ddb5-03f0-4734-9d34-07d590727306 and dequeue count = 2
[2023-08-23T09:23:19.896Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Received a duplicate message [TaskCompleted#179] from ldevtest-control-03 with ID = f407e496-9aae-4e49-9165-df1f9a4a4418 and dequeue count = 2
[2023-08-23T09:23:27.053Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Received a duplicate message [TaskCompleted#79] from ldevtest-control-03 with ID = 9627b228-5c86-4582-b379-44042ad352a6 and dequeue count = 2
[2023-08-23T09:23:27.053Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Received a duplicate message [TaskCompleted#198] from ldevtest-control-03 with ID = 749df5dc-eb9a-4aeb-af29-c5769343071b and dequeue count = 2
[2023-08-23T09:23:29.090Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Received a duplicate message [TaskCompleted#158] from ldevtest-control-03 with ID = c2d25501-9e0c-4e96-b9f5-5ee3dfa93b9f and dequeue count = 2
[2023-08-23T09:23:29.090Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Received a duplicate message [TaskCompleted#187] from ldevtest-control-03 with ID = 97c8a3ac-66ad-4a50-a1a3-9eaba7de2a9a and dequeue count = 2
[2023-08-23T09:23:29.163Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Received a duplicate message [TaskCompleted#114] from ldevtest-control-03 with ID = 8f84bc0c-93d3-46c5-8591-8f45ec73693e and dequeue count = 2
[2023-08-23T09:23:30.265Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Received a duplicate message [TaskCompleted#193] from ldevtest-control-03 with ID = ea33b29f-4161-4d33-9e0a-5a68b6a83a29 and dequeue count = 2
[2023-08-23T09:23:30.850Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Received a duplicate message [TaskCompleted#184] from ldevtest-control-03 with ID = f55774fe-eadb-4653-9407-92ae21daae8f and dequeue count = 2
[2023-08-23T09:25:46.450Z] 16c71eff-8b20-4525-a7c0-0c61028d5eae: Received a duplicate message [TaskCompleted#133] from ldevtest-control-03 with ID = c1127736-0bf3-4b6e-906b-1a8209442e11 and dequeue count = 2
[2023-08-23T09:27:45.644Z] Timeout value of 00:10:00 exceeded by function 'Functions.of-test-orchestrator' (Id: '34fdc268-4512-468a-addc-6ea37eb1ae26'). Initiating cancellation.
[2023-08-23T09:27:45.645Z] Executed 'Functions.of-test-orchestrator' (Failed, Id=34fdc268-4512-468a-addc-6ea37eb1ae26, Duration=600008ms)
[2023-08-23T09:27:45.645Z] Microsoft.Azure.WebJobs.Host: Timeout value of 00:10:00 was exceeded by function: Functions.of-test-orchestrator.
[2023-08-23T09:27:47.644Z] A function timeout has occurred. Restarting worker process executing invocationId '34fdc268-4512-468a-addc-6ea37eb1ae26'.

 *  The terminal process "/usr/bin/pwsh '-NoProfile', '-c', 'func host start --verbose'" terminated with exit code: 143. 
 *  Terminal will be reused by tasks, press any key to close it.

So as you can see from the 2 attempts the first run succeeded with all 200 I tried and took a mere 3m44s:

yet the second time, 2m4s in it bailed. Some activities completed, other have not even started yet:

I stopped here and have pushed the exact code I am using as I believe it should allow for replicating the issue yourself.

Hopefully the above helps but if you need anything further please let me know!

ruankrTs commented 1 year ago

Hi @davidmrdavid . Just wanted to add some more to this. So after I got the behaviour yesterday I ended up simply restarting the function a few times. It pretty much just looped through above behaviour endlessly, ultimately timing out again. I then purged the instance (using Durable functions monitor) and still have strange behaviour. It seems the run is stuck somewhere as I get what seems like constant re-schedules and abandons:

Functions:

        sa-debug-function: [GET,POST] http://localhost:7071/api/sa-debug-function

        af-test-activity1: activityTrigger

        of-test-orchestrator: orchestrationTrigger

        tf-fifio-test: serviceBusTrigger

[2023-08-24T09:09:31.631Z] Task hub worker started. Latency: 00:00:00.5037274. InstanceId: . Function: . HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.3. SequenceNumber: 2.
[2023-08-24T09:09:31.945Z] Worker process started and initialized.
[2023-08-24T09:09:32.147Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Message [TaskCompleted#84] was received out of order and will be temporarily returned back to ldevtest-control-00
[2023-08-24T09:09:32.148Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Message [TaskCompleted#137] was received out of order and will be temporarily returned back to ldevtest-control-00
[2023-08-24T09:09:32.148Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Message [TaskFailed#55] was received out of order and will be temporarily returned back to ldevtest-control-00
[2023-08-24T09:09:32.148Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Message [TaskFailed#161] was received out of order and will be temporarily returned back to ldevtest-control-00
[2023-08-24T09:09:32.156Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Abandoning [TaskCompleted#84] message back to ldevtest-control-00 and setting a visibility delay of 32ms
[2023-08-24T09:09:32.159Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Abandoning [TaskCompleted#137] message back to ldevtest-control-00 and setting a visibility delay of 16ms
[2023-08-24T09:09:32.159Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Abandoning [TaskFailed#55] message back to ldevtest-control-00 and setting a visibility delay of 2ms
[2023-08-24T09:09:32.159Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Abandoning [TaskFailed#161] message back to ldevtest-control-00 and setting a visibility delay of 2ms
[2023-08-24T09:09:32.175Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Discarding 1 dequeued history event(s): No such instance
[2023-08-24T09:09:35.509Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Message [TaskFailed#55] was received out of order and will be temporarily returned back to ldevtest-control-00
[2023-08-24T09:09:35.509Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Message [TaskFailed#161] was received out of order and will be temporarily returned back to ldevtest-control-00
[2023-08-24T09:09:35.509Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Abandoning [TaskFailed#55] message back to ldevtest-control-00 and setting a visibility delay of 4ms
[2023-08-24T09:09:35.510Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Abandoning [TaskFailed#161] message back to ldevtest-control-00 and setting a visibility delay of 4ms
[2023-08-24T09:09:36.048Z] Host lock lease acquired by instance ID '000000000000000000000000B3395018'.
[2023-08-24T09:09:42.408Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Message [TaskFailed#55] was received out of order and will be temporarily returned back to ldevtest-control-00
[2023-08-24T09:09:42.409Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Message [TaskFailed#161] was received out of order and will be temporarily returned back to ldevtest-control-00
[2023-08-24T09:09:42.409Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Abandoning [TaskFailed#55] message back to ldevtest-control-00 and setting a visibility delay of 8ms
[2023-08-24T09:09:42.409Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Abandoning [TaskFailed#161] message back to ldevtest-control-00 and setting a visibility delay of 8ms
[2023-08-24T09:09:49.352Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Message [TaskCompleted#137] was received out of order and will be temporarily returned back to ldevtest-control-00
[2023-08-24T09:09:49.352Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Abandoning [TaskCompleted#137] message back to ldevtest-control-00 and setting a visibility delay of 32ms
[2023-08-24T09:09:50.460Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Message [TaskFailed#55] was received out of order and will be temporarily returned back to ldevtest-control-00
[2023-08-24T09:09:50.460Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Message [TaskFailed#161] was received out of order and will be temporarily returned back to ldevtest-control-00
[2023-08-24T09:09:50.460Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Abandoning [TaskFailed#55] message back to ldevtest-control-00 and setting a visibility delay of 16ms
[2023-08-24T09:09:50.460Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Abandoning [TaskFailed#161] message back to ldevtest-control-00 and setting a visibility delay of 16ms
[2023-08-24T09:10:18.008Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Message [TaskFailed#55] was received out of order and will be temporarily returned back to ldevtest-control-00
[2023-08-24T09:10:18.009Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Message [TaskFailed#161] was received out of order and will be temporarily returned back to ldevtest-control-00
[2023-08-24T09:10:18.009Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Abandoning [TaskFailed#55] message back to ldevtest-control-00 and setting a visibility delay of 32ms
[2023-08-24T09:10:18.009Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Abandoning [TaskFailed#161] message back to ldevtest-control-00 and setting a visibility delay of 32ms
[2023-08-24T09:10:18.026Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Discarding 1 dequeued history event(s): No such instance
[2023-08-24T09:10:21.425Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Discarding 1 dequeued history event(s): No such instance
[2023-08-24T09:11:16.189Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Discarding 2 dequeued history event(s): No such instance
[2023-08-24T09:11:24.606Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Function 'af-test-activity1 (Activity)' started. IsReplay: False. Input: (180 bytes). State: Started. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.3. SequenceNumber: 3. TaskEventId: 139
[2023-08-24T09:11:24.614Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Function 'af-test-activity1 (Activity)' started. IsReplay: False. Input: (180 bytes). State: Started. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.3. SequenceNumber: 4. TaskEventId: 159
[2023-08-24T09:11:24.628Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Function 'af-test-activity1 (Activity)' started. IsReplay: False. Input: (180 bytes). State: Started. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.3. SequenceNumber: 5. TaskEventId: 20
[2023-08-24T09:11:24.642Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Function 'af-test-activity1 (Activity)' started. IsReplay: False. Input: (180 bytes). State: Started. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.3. SequenceNumber: 6. TaskEventId: 26
[2023-08-24T09:11:24.656Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Function 'af-test-activity1 (Activity)' started. IsReplay: False. Input: (180 bytes). State: Started. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.3. SequenceNumber: 7. TaskEventId: 92
[2023-08-24T09:11:24.678Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Function 'af-test-activity1 (Activity)' started. IsReplay: False. Input: (180 bytes). State: Started. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.3. SequenceNumber: 8. TaskEventId: 53
[2023-08-24T09:11:24.693Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Function 'af-test-activity1 (Activity)' started. IsReplay: False. Input: (180 bytes). State: Started. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.3. SequenceNumber: 9. TaskEventId: 75
[2023-08-24T09:11:24.707Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Function 'af-test-activity1 (Activity)' started. IsReplay: False. Input: (180 bytes). State: Started. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.3. SequenceNumber: 10. TaskEventId: 40
[2023-08-24T09:11:24.720Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Function 'af-test-activity1 (Activity)' started. IsReplay: False. Input: (180 bytes). State: Started. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.3. SequenceNumber: 11. TaskEventId: 192
[2023-08-24T09:11:24.738Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Function 'af-test-activity1 (Activity)' started. IsReplay: False. Input: (184 bytes). State: Started. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.3. SequenceNumber: 12. TaskEventId: 110
[2023-08-24T09:11:24.751Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Function 'af-test-activity1 (Activity)' started. IsReplay: False. Input: (184 bytes). State: Started. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.3. SequenceNumber: 13. TaskEventId: 152
[2023-08-24T09:11:24.764Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Function 'af-test-activity1 (Activity)' started. IsReplay: False. Input: (184 bytes). State: Started. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.3. SequenceNumber: 14. TaskEventId: 125
[2023-08-24T09:11:24.780Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Function 'af-test-activity1 (Activity)' started. IsReplay: False. Input: (192 bytes). State: Started. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.3. SequenceNumber: 15. TaskEventId: 116
[2023-08-24T09:11:24.869Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Function 'af-test-activity1 (Activity)' started. IsReplay: False. Input: (180 bytes). State: Started. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.3. SequenceNumber: 16. TaskEventId: 59
[2023-08-24T09:11:24.886Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Function 'af-test-activity1 (Activity)' started. IsReplay: False. Input: (184 bytes). State: Started. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.3. SequenceNumber: 17. TaskEventId: 78
[2023-08-24T09:11:25.096Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Function 'af-test-activity1 (Activity)' started. IsReplay: False. Input: (180 bytes). State: Started. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.3. SequenceNumber: 18. TaskEventId: 170
[2023-08-24T09:11:25.110Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Function 'af-test-activity1 (Activity)' started. IsReplay: False. Input: (180 bytes). State: Started. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.3. SequenceNumber: 19. TaskEventId: 184
[2023-08-24T09:11:25.124Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Function 'af-test-activity1 (Activity)' started. IsReplay: False. Input: (180 bytes). State: Started. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.3. SequenceNumber: 20. TaskEventId: 153
[2023-08-24T09:11:25.137Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Function 'af-test-activity1 (Activity)' started. IsReplay: False. Input: (180 bytes). State: Started. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.3. SequenceNumber: 21. TaskEventId: 35
[2023-08-24T09:11:25.162Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Function 'af-test-activity1 (Activity)' started. IsReplay: False. Input: (180 bytes). State: Started. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.3. SequenceNumber: 22. TaskEventId: 198
[2023-08-24T09:11:25.177Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Function 'af-test-activity1 (Activity)' started. IsReplay: False. Input: (176 bytes). State: Started. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.3. SequenceNumber: 23. TaskEventId: 30
[2023-08-24T09:11:26.346Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Function 'af-test-activity1 (Activity)' started. IsReplay: False. Input: (184 bytes). State: Started. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.3. SequenceNumber: 24. TaskEventId: 13
[2023-08-24T09:11:26.966Z] INFORMATION: connected function to azure using spn
[2023-08-24T09:11:26.966Z] INFORMATION: profile load completed
[2023-08-24T09:11:27.000Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Function 'af-test-activity1 (Activity)' started. IsReplay: False. Input: (184 bytes). State: Started. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.3. SequenceNumber: 25. TaskEventId: 196
[2023-08-24T09:11:27.014Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Function 'af-test-activity1 (Activity)' started. IsReplay: False. Input: (184 bytes). State: Started. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.3. SequenceNumber: 26. TaskEventId: 27
[2023-08-24T09:11:27.027Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Function 'af-test-activity1 (Activity)' started. IsReplay: False. Input: (180 bytes). State: Started. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.3. SequenceNumber: 27. TaskEventId: 71
[2023-08-24T09:11:27.039Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Function 'af-test-activity1 (Activity)' started. IsReplay: False. Input: (180 bytes). State: Started. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.3. SequenceNumber: 28. TaskEventId: 81
[2023-08-24T09:11:27.052Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Function 'af-test-activity1 (Activity)' started. IsReplay: False. Input: (192 bytes). State: Started. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.3. SequenceNumber: 29. TaskEventId: 120
[2023-08-24T09:11:27.066Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Function 'af-test-activity1 (Activity)' started. IsReplay: False. Input: (176 bytes). State: Started. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.3. SequenceNumber: 30. TaskEventId: 66
[2023-08-24T09:11:27.081Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Function 'af-test-activity1 (Activity)' started. IsReplay: False. Input: (188 bytes). State: Started. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.3. SequenceNumber: 31. TaskEventId: 80
[2023-08-24T09:11:27.096Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Function 'af-test-activity1 (Activity)' started. IsReplay: False. Input: (176 bytes). State: Started. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.3. SequenceNumber: 32. TaskEventId: 43
[2023-08-24T09:11:30.759Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Function 'af-test-activity1 (Activity)' started. IsReplay: False. Input: (180 bytes). State: Started. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.3. SequenceNumber: 33. TaskEventId: 65
[2023-08-24T09:11:30.772Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Function 'af-test-activity1 (Activity)' started. IsReplay: False. Input: (180 bytes). State: Started. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.3. SequenceNumber: 34. TaskEventId: 97
[2023-08-24T09:11:30.784Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Function 'af-test-activity1 (Activity)' started. IsReplay: False. Input: (184 bytes). State: Started. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.3. SequenceNumber: 35. TaskEventId: 138
[2023-08-24T09:11:30.796Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Function 'af-test-activity1 (Activity)' started. IsReplay: False. Input: (180 bytes). State: Started. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.3. SequenceNumber: 36. TaskEventId: 82
[2023-08-24T09:11:30.811Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Function 'af-test-activity1 (Activity)' started. IsReplay: False. Input: (172 bytes). State: Started. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.3. SequenceNumber: 37. TaskEventId: 162
[2023-08-24T09:11:30.826Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Function 'af-test-activity1 (Activity)' started. IsReplay: False. Input: (184 bytes). State: Started. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.3. SequenceNumber: 38. TaskEventId: 147
[2023-08-24T09:11:30.845Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Function 'af-test-activity1 (Activity)' started. IsReplay: False. Input: (180 bytes). State: Started. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.3. SequenceNumber: 39. TaskEventId: 148
[2023-08-24T09:11:30.865Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Function 'af-test-activity1 (Activity)' started. IsReplay: False. Input: (188 bytes). State: Started. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.3. SequenceNumber: 40. TaskEventId: 195
[2023-08-24T09:11:31.317Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Function 'af-test-activity1 (Activity)' started. IsReplay: False. Input: (180 bytes). State: Started. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.3. SequenceNumber: 41. TaskEventId: 118
[2023-08-24T09:11:31.654Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Function 'af-test-activity1 (Activity)' started. IsReplay: False. Input: (184 bytes). State: Started. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.3. SequenceNumber: 42. TaskEventId: 112
[2023-08-24T09:11:31.848Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Function 'af-test-activity1 (Activity)' started. IsReplay: False. Input: (180 bytes). State: Started. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.3. SequenceNumber: 43. TaskEventId: 175
[2023-08-24T09:11:35.135Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Function 'af-test-activity1 (Activity)' started. IsReplay: False. Input: (180 bytes). State: Started. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.3. SequenceNumber: 44. TaskEventId: 52
[2023-08-24T09:11:35.149Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Function 'af-test-activity1 (Activity)' started. IsReplay: False. Input: (176 bytes). State: Started. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.3. SequenceNumber: 45. TaskEventId: 103
[2023-08-24T09:11:35.163Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Function 'af-test-activity1 (Activity)' started. IsReplay: False. Input: (176 bytes). State: Started. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.3. SequenceNumber: 46. TaskEventId: 91
[2023-08-24T09:11:35.179Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Function 'af-test-activity1 (Activity)' started. IsReplay: False. Input: (184 bytes). State: Started. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.3. SequenceNumber: 47. TaskEventId: 24
[2023-08-24T09:11:35.194Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Function 'af-test-activity1 (Activity)' started. IsReplay: False. Input: (176 bytes). State: Started. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.3. SequenceNumber: 48. TaskEventId: 127
[2023-08-24T09:11:35.209Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Function 'af-test-activity1 (Activity)' started. IsReplay: False. Input: (176 bytes). State: Started. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.3. SequenceNumber: 49. TaskEventId: 22
[2023-08-24T09:11:35.292Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Function 'af-test-activity1 (Activity)' started. IsReplay: False. Input: (184 bytes). State: Started. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.3. SequenceNumber: 50. TaskEventId: 57
[2023-08-24T09:11:36.397Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Function 'af-test-activity1 (Activity)' started. IsReplay: False. Input: (184 bytes). State: Started. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.3. SequenceNumber: 51. TaskEventId: 74
[2023-08-24T09:11:36.414Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Function 'af-test-activity1 (Activity)' started. IsReplay: False. Input: (176 bytes). State: Started. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.3. SequenceNumber: 52. TaskEventId: 98
[2023-08-24T09:11:37.027Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Function 'af-test-activity1 (Activity)' started. IsReplay: False. Input: (184 bytes). State: Started. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.3. SequenceNumber: 53. TaskEventId: 89
[2023-08-24T09:11:37.114Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Function 'af-test-activity1 (Activity)' started. IsReplay: False. Input: (180 bytes). State: Started. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.3. SequenceNumber: 54. TaskEventId: 144
[2023-08-24T09:11:40.551Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Function 'af-test-activity1 (Activity)' started. IsReplay: False. Input: (176 bytes). State: Started. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.3. SequenceNumber: 55. TaskEventId: 124
[2023-08-24T09:11:40.566Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Function 'af-test-activity1 (Activity)' started. IsReplay: False. Input: (176 bytes). State: Started. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.3. SequenceNumber: 56. TaskEventId: 21
[2023-08-24T09:11:40.585Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Function 'af-test-activity1 (Activity)' started. IsReplay: False. Input: (188 bytes). State: Started. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.3. SequenceNumber: 57. TaskEventId: 39
[2023-08-24T09:11:40.601Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Function 'af-test-activity1 (Activity)' started. IsReplay: False. Input: (180 bytes). State: Started. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.3. SequenceNumber: 58. TaskEventId: 104
[2023-08-24T09:11:40.613Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Function 'af-test-activity1 (Activity)' started. IsReplay: False. Input: (184 bytes). State: Started. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.3. SequenceNumber: 59. TaskEventId: 51
[2023-08-24T09:11:40.626Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Function 'af-test-activity1 (Activity)' started. IsReplay: False. Input: (176 bytes). State: Started. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.3. SequenceNumber: 60. TaskEventId: 114
[2023-08-24T09:11:40.642Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Function 'af-test-activity1 (Activity)' started. IsReplay: False. Input: (180 bytes). State: Started. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.3. SequenceNumber: 61. TaskEventId: 18
[2023-08-24T09:11:40.660Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Function 'af-test-activity1 (Activity)' started. IsReplay: False. Input: (180 bytes). State: Started. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.3. SequenceNumber: 62. TaskEventId: 156
[2023-08-24T09:11:40.672Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Function 'af-test-activity1 (Activity)' started. IsReplay: False. Input: (188 bytes). State: Started. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.3. SequenceNumber: 63. TaskEventId: 46
[2023-08-24T09:11:40.685Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Function 'af-test-activity1 (Activity)' started. IsReplay: False. Input: (180 bytes). State: Started. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.3. SequenceNumber: 64. TaskEventId: 178
[2023-08-24T09:11:40.701Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Function 'af-test-activity1 (Activity)' started. IsReplay: False. Input: (176 bytes). State: Started. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.3. SequenceNumber: 65. TaskEventId: 100
[2023-08-24T09:11:40.715Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Function 'af-test-activity1 (Activity)' started. IsReplay: False. Input: (180 bytes). State: Started. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.3. SequenceNumber: 66. TaskEventId: 41
[2023-08-24T09:11:40.732Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Function 'af-test-activity1 (Activity)' started. IsReplay: False. Input: (184 bytes). State: Started. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.3. SequenceNumber: 67. TaskEventId: 145
[2023-08-24T09:11:40.744Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Function 'af-test-activity1 (Activity)' started. IsReplay: False. Input: (188 bytes). State: Started. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.3. SequenceNumber: 68. TaskEventId: 99
[2023-08-24T09:11:40.759Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Function 'af-test-activity1 (Activity)' started. IsReplay: False. Input: (180 bytes). State: Started. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.3. SequenceNumber: 69. TaskEventId: 188
[2023-08-24T09:11:40.771Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Function 'af-test-activity1 (Activity)' started. IsReplay: False. Input: (180 bytes). State: Started. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.3. SequenceNumber: 70. TaskEventId: 86
[2023-08-24T09:11:40.786Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Function 'af-test-activity1 (Activity)' started. IsReplay: False. Input: (180 bytes). State: Started. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.3. SequenceNumber: 71. TaskEventId: 197
[2023-08-24T09:11:40.800Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Function 'af-test-activity1 (Activity)' started. IsReplay: False. Input: (188 bytes). State: Started. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.3. SequenceNumber: 72. TaskEventId: 85
[2023-08-24T09:11:41.406Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Function 'af-test-activity1 (Activity)' started. IsReplay: False. Input: (180 bytes). State: Started. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.3. SequenceNumber: 73. TaskEventId: 60
[2023-08-24T09:11:44.018Z] INFORMATION: test-item-97 completed in [0.28]
[2023-08-24T09:11:44.053Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Function 'af-test-activity1 (Activity)' completed. ContinuedAsNew: False. IsReplay: False. Output: (164 bytes). State: Completed. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.3. SequenceNumber: 74. TaskEventId: 26
[2023-08-24T09:11:44.108Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Message [TaskCompleted#26] was received out of order and will be temporarily returned back to ldevtest-control-00
[2023-08-24T09:11:44.108Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Abandoning [TaskCompleted#26] message back to ldevtest-control-00 and setting a visibility delay of 2ms
[2023-08-24T09:11:45.207Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Function 'af-test-activity1 (Activity)' started. IsReplay: False. Input: (176 bytes). State: Started. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.3. SequenceNumber: 75. TaskEventId: 161
[2023-08-24T09:11:45.220Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Function 'af-test-activity1 (Activity)' started. IsReplay: False. Input: (180 bytes). State: Started. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.3. SequenceNumber: 76. TaskEventId: 130
[2023-08-24T09:11:45.232Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Function 'af-test-activity1 (Activity)' started. IsReplay: False. Input: (180 bytes). State: Started. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.3. SequenceNumber: 77. TaskEventId: 193
[2023-08-24T09:11:45.247Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Function 'af-test-activity1 (Activity)' started. IsReplay: False. Input: (180 bytes). State: Started. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.3. SequenceNumber: 78. TaskEventId: 73
[2023-08-24T09:11:45.262Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Function 'af-test-activity1 (Activity)' started. IsReplay: False. Input: (184 bytes). State: Started. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.3. SequenceNumber: 79. TaskEventId: 63
[2023-08-24T09:11:45.275Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Function 'af-test-activity1 (Activity)' started. IsReplay: False. Input: (184 bytes). State: Started. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.3. SequenceNumber: 80. TaskEventId: 48
[2023-08-24T09:11:46.388Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Function 'af-test-activity1 (Activity)' started. IsReplay: False. Input: (188 bytes). State: Started. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.3. SequenceNumber: 81. TaskEventId: 32
[2023-08-24T09:11:46.401Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Function 'af-test-activity1 (Activity)' started. IsReplay: False. Input: (184 bytes). State: Started. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.3. SequenceNumber: 82. TaskEventId: 169
[2023-08-24T09:11:46.417Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Function 'af-test-activity1 (Activity)' started. IsReplay: False. Input: (176 bytes). State: Started. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.3. SequenceNumber: 83. TaskEventId: 108
[2023-08-24T09:11:46.429Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Function 'af-test-activity1 (Activity)' started. IsReplay: False. Input: (180 bytes). State: Started. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.3. SequenceNumber: 84. TaskEventId: 111
[2023-08-24T09:11:46.441Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Function 'af-test-activity1 (Activity)' started. IsReplay: False. Input: (176 bytes). State: Started. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.3. SequenceNumber: 85. TaskEventId: 185
[2023-08-24T09:11:46.454Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Function 'af-test-activity1 (Activity)' started. IsReplay: False. Input: (180 bytes). State: Started. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.3. SequenceNumber: 86. TaskEventId: 37
[2023-08-24T09:11:46.466Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Function 'af-test-activity1 (Activity)' started. IsReplay: False. Input: (172 bytes). State: Started. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.3. SequenceNumber: 87. TaskEventId: 199
[2023-08-24T09:11:46.668Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Function 'af-test-activity1 (Activity)' started. IsReplay: False. Input: (180 bytes). State: Started. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.3. SequenceNumber: 88. TaskEventId: 47
[2023-08-24T09:11:46.682Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Function 'af-test-activity1 (Activity)' started. IsReplay: False. Input: (180 bytes). State: Started. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.3. SequenceNumber: 89. TaskEventId: 154
[2023-08-24T09:11:46.872Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Function 'af-test-activity1 (Activity)' started. IsReplay: False. Input: (180 bytes). State: Started. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.3. SequenceNumber: 90. TaskEventId: 142
[2023-08-24T09:11:46.887Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Function 'af-test-activity1 (Activity)' started. IsReplay: False. Input: (180 bytes). State: Started. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.3. SequenceNumber: 91. TaskEventId: 33
[2023-08-24T09:11:47.393Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Message [TaskCompleted#26] was received out of order and will be temporarily returned back to ldevtest-control-00
[2023-08-24T09:11:47.393Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Abandoning [TaskCompleted#26] message back to ldevtest-control-00 and setting a visibility delay of 4ms
[2023-08-24T09:11:50.558Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Function 'af-test-activity1 (Activity)' started. IsReplay: False. Input: (176 bytes). State: Started. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.3. SequenceNumber: 92. TaskEventId: 172
[2023-08-24T09:11:50.572Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Function 'af-test-activity1 (Activity)' started. IsReplay: False. Input: (176 bytes). State: Started. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.3. SequenceNumber: 93. TaskEventId: 44
[2023-08-24T09:11:50.590Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Function 'af-test-activity1 (Activity)' started. IsReplay: False. Input: (192 bytes). State: Started. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.3. SequenceNumber: 94. TaskEventId: 146
[2023-08-24T09:11:50.605Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Function 'af-test-activity1 (Activity)' started. IsReplay: False. Input: (176 bytes). State: Started. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.3. SequenceNumber: 95. TaskEventId: 95
[2023-08-24T09:11:50.617Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Function 'af-test-activity1 (Activity)' started. IsReplay: False. Input: (184 bytes). State: Started. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.3. SequenceNumber: 96. TaskEventId: 68
[2023-08-24T09:11:50.658Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Function 'af-test-activity1 (Activity)' started. IsReplay: False. Input: (184 bytes). State: Started. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.3. SequenceNumber: 97. TaskEventId: 106
[2023-08-24T09:11:50.672Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Function 'af-test-activity1 (Activity)' started. IsReplay: False. Input: (180 bytes). State: Started. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.3. SequenceNumber: 98. TaskEventId: 165
[2023-08-24T09:11:50.687Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Function 'af-test-activity1 (Activity)' started. IsReplay: False. Input: (192 bytes). State: Started. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.3. SequenceNumber: 99. TaskEventId: 182
[2023-08-24T09:11:50.701Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Function 'af-test-activity1 (Activity)' started. IsReplay: False. Input: (176 bytes). State: Started. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.3. SequenceNumber: 100. TaskEventId: 54
[2023-08-24T09:11:50.716Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Function 'af-test-activity1 (Activity)' started. IsReplay: False. Input: (180 bytes). State: Started. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.3. SequenceNumber: 101. TaskEventId: 194
[2023-08-24T09:11:50.744Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Function 'af-test-activity1 (Activity)' started. IsReplay: False. Input: (180 bytes). State: Started. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.3. SequenceNumber: 102. TaskEventId: 76
[2023-08-24T09:11:50.770Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Function 'af-test-activity1 (Activity)' started. IsReplay: False. Input: (184 bytes). State: Started. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.3. SequenceNumber: 103. TaskEventId: 186
[2023-08-24T09:11:50.783Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Function 'af-test-activity1 (Activity)' started. IsReplay: False. Input: (172 bytes). State: Started. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.3. SequenceNumber: 104. TaskEventId: 29
[2023-08-24T09:11:50.796Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Function 'af-test-activity1 (Activity)' started. IsReplay: False. Input: (184 bytes). State: Started. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.3. SequenceNumber: 105. TaskEventId: 164
[2023-08-24T09:11:50.815Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Function 'af-test-activity1 (Activity)' started. IsReplay: False. Input: (176 bytes). State: Started. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.3. SequenceNumber: 106. TaskEventId: 49
[2023-08-24T09:11:51.000Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Message [TaskFailed#79] was received out of order and will be temporarily returned back to ldevtest-control-00
[2023-08-24T09:11:51.000Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Abandoning [TaskFailed#79] message back to ldevtest-control-00 and setting a visibility delay of 4ms
[2023-08-24T09:11:51.615Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Message [TaskCompleted#26] was received out of order and will be temporarily returned back to ldevtest-control-00
[2023-08-24T09:11:51.615Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Abandoning [TaskCompleted#26] message back to ldevtest-control-00 and setting a visibility delay of 8ms
[2023-08-24T09:11:55.594Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Message [TaskFailed#79] was received out of order and will be temporarily returned back to ldevtest-control-00
[2023-08-24T09:11:55.594Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Abandoning [TaskFailed#79] message back to ldevtest-control-00 and setting a visibility delay of 8ms
[2023-08-24T09:11:59.031Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Function 'af-test-activity1 (Activity)' completed. ContinuedAsNew: False. IsReplay: False. Output: (164 bytes). State: Completed. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.3. SequenceNumber: 107. TaskEventId: 20
[2023-08-24T09:11:59.172Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Message [TaskCompleted#20] was received out of order and will be temporarily returned back to ldevtest-control-00
[2023-08-24T09:11:59.172Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Abandoning [TaskCompleted#20] message back to ldevtest-control-00 and setting a visibility delay of 2ms
[2023-08-24T09:11:59.769Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Message [TaskCompleted#26] was received out of order and will be temporarily returned back to ldevtest-control-00
[2023-08-24T09:11:59.769Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Abandoning [TaskCompleted#26] message back to ldevtest-control-00 and setting a visibility delay of 16ms
[2023-08-24T09:12:01.842Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Message [TaskCompleted#20] was received out of order and will be temporarily returned back to ldevtest-control-00
[2023-08-24T09:12:01.842Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Abandoning [TaskCompleted#20] message back to ldevtest-control-00 and setting a visibility delay of 4ms
[2023-08-24T09:12:03.739Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Message [TaskFailed#79] was received out of order and will be temporarily returned back to ldevtest-control-00
[2023-08-24T09:12:03.739Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Abandoning [TaskFailed#79] message back to ldevtest-control-00 and setting a visibility delay of 16ms
[2023-08-24T09:12:07.257Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Message [TaskCompleted#20] was received out of order and will be temporarily returned back to ldevtest-control-00
[2023-08-24T09:12:07.257Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Abandoning [TaskCompleted#20] message back to ldevtest-control-00 and setting a visibility delay of 8ms
[2023-08-24T09:12:10.034Z] INFORMATION: test-item-195 completed in [0.18]
[2023-08-24T09:12:10.035Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Function 'af-test-activity1 (Activity)' completed. ContinuedAsNew: False. IsReplay: False. Output: (168 bytes). State: Completed. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.3. SequenceNumber: 108. TaskEventId: 92
[2023-08-24T09:12:10.095Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Message [TaskCompleted#92] was received out of order and will be temporarily returned back to ldevtest-control-00
[2023-08-24T09:12:10.095Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Abandoning [TaskCompleted#92] message back to ldevtest-control-00 and setting a visibility delay of 2ms
[2023-08-24T09:12:13.758Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Message [TaskCompleted#92] was received out of order and will be temporarily returned back to ldevtest-control-00
[2023-08-24T09:12:13.758Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Abandoning [TaskCompleted#92] message back to ldevtest-control-00 and setting a visibility delay of 4ms
[2023-08-24T09:12:15.552Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Message [TaskCompleted#20] was received out of order and will be temporarily returned back to ldevtest-control-00
[2023-08-24T09:12:15.552Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Abandoning [TaskCompleted#20] message back to ldevtest-control-00 and setting a visibility delay of 16ms
[2023-08-24T09:12:15.929Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Message [TaskCompleted#26] was received out of order and will be temporarily returned back to ldevtest-control-00
[2023-08-24T09:12:15.929Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Abandoning [TaskCompleted#26] message back to ldevtest-control-00 and setting a visibility delay of 32ms
[2023-08-24T09:12:18.043Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Message [TaskCompleted#92] was received out of order and will be temporarily returned back to ldevtest-control-00
[2023-08-24T09:12:18.043Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Abandoning [TaskCompleted#92] message back to ldevtest-control-00 and setting a visibility delay of 8ms
[2023-08-24T09:12:20.074Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Message [TaskFailed#79] was received out of order and will be temporarily returned back to ldevtest-control-00
[2023-08-24T09:12:20.074Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Abandoning [TaskFailed#79] message back to ldevtest-control-00 and setting a visibility delay of 32ms
[2023-08-24T09:12:27.317Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Message [TaskCompleted#92] was received out of order and will be temporarily returned back to ldevtest-control-00
[2023-08-24T09:12:27.317Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Abandoning [TaskCompleted#92] message back to ldevtest-control-00 and setting a visibility delay of 16ms
[2023-08-24T09:12:33.706Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Message [TaskCompleted#20] was received out of order and will be temporarily returned back to ldevtest-control-00
[2023-08-24T09:12:33.706Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Abandoning [TaskCompleted#20] message back to ldevtest-control-00 and setting a visibility delay of 32ms

As before this will eventually lead to a timeout

[2023-08-24T09:21:23.147Z] INFORMATION: test-item-69 completed in [0.17]
[2023-08-24T09:21:23.148Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Function 'af-test-activity1 (Activity)' completed. ContinuedAsNew: False. IsReplay: False. Output: (164 bytes). State: Completed. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.3. SequenceNumber: 123. TaskEventId: 153
[2023-08-24T09:21:23.237Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Message [TaskCompleted#184] was received out of order and will be temporarily returned back to ldevtest-control-00
[2023-08-24T09:21:23.237Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Message [TaskCompleted#153] was received out of order and will be temporarily returned back to ldevtest-control-00
[2023-08-24T09:21:23.237Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Abandoning [TaskCompleted#184] message back to ldevtest-control-00 and setting a visibility delay of 8ms
[2023-08-24T09:21:23.237Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Abandoning [TaskCompleted#153] message back to ldevtest-control-00 and setting a visibility delay of 2ms
[2023-08-24T09:21:25.132Z] Timeout value of 00:10:00 exceeded by function 'Functions.af-test-activity1' (Id: '5d051c57-208a-4d18-a837-096dcfd6c837'). Initiating cancellation.
[2023-08-24T09:21:25.150Z] Executed 'Functions.af-test-activity1' (Failed, Id=5d051c57-208a-4d18-a837-096dcfd6c837, Duration=600000ms)
[2023-08-24T09:21:25.151Z] Microsoft.Azure.WebJobs.Host: Timeout value of 00:10:00 was exceeded by function: Functions.af-test-activity1.
[2023-08-24T09:21:25.161Z] Timeout value of 00:10:00 exceeded by function 'Functions.af-test-activity1' (Id: '2fb27ec7-ba10-4f58-8837-faeafecf85c0'). Initiating cancellation.
[2023-08-24T09:21:25.162Z] Executed 'Functions.af-test-activity1' (Failed, Id=2fb27ec7-ba10-4f58-8837-faeafecf85c0, Duration=599999ms)
[2023-08-24T09:21:25.162Z] Microsoft.Azure.WebJobs.Host: Timeout value of 00:10:00 was exceeded by function: Functions.af-test-activity1.
[2023-08-24T09:21:25.170Z] Timeout value of 00:10:00 exceeded by function 'Functions.af-test-activity1' (Id: '9fb81255-a989-4fa8-8ef1-16d7d07c1ee2'). Initiating cancellation.
[2023-08-24T09:21:25.171Z] Executed 'Functions.af-test-activity1' (Failed, Id=9fb81255-a989-4fa8-8ef1-16d7d07c1ee2, Duration=599993ms)
[2023-08-24T09:21:25.171Z] Microsoft.Azure.WebJobs.Host: Timeout value of 00:10:00 was exceeded by function: Functions.af-test-activity1.
[2023-08-24T09:21:26.335Z] Timeout value of 00:10:00 exceeded by function 'Functions.af-test-activity1' (Id: '11052b31-83e8-40e2-a4fa-8e5295df394a'). Initiating cancellation.
[2023-08-24T09:21:26.335Z] Executed 'Functions.af-test-activity1' (Failed, Id=11052b31-83e8-40e2-a4fa-8e5295df394a, Duration=599988ms)
[2023-08-24T09:21:26.335Z] Microsoft.Azure.WebJobs.Host: Timeout value of 00:10:00 was exceeded by function: Functions.af-test-activity1.
[2023-08-24T09:21:26.788Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Message [TaskCompleted#153] was received out of order and will be temporarily returned back to ldevtest-control-00
[2023-08-24T09:21:26.788Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Abandoning [TaskCompleted#153] message back to ldevtest-control-00 and setting a visibility delay of 4ms
[2023-08-24T09:21:27.000Z] Timeout value of 00:10:00 exceeded by function 'Functions.af-test-activity1' (Id: '39d5fa10-4cf4-43e7-88a4-f71d8a6d7382'). Initiating cancellation.
[2023-08-24T09:21:27.000Z] Timeout value of 00:10:00 exceeded by function 'Functions.af-test-activity1' (Id: '3dbab2d8-74fe-4c2c-988f-ada8621e27a0'). Initiating cancellation.
[2023-08-24T09:21:27.001Z] Executed 'Functions.af-test-activity1' (Failed, Id=39d5fa10-4cf4-43e7-88a4-f71d8a6d7382, Duration=599986ms)
[2023-08-24T09:21:27.001Z] Microsoft.Azure.WebJobs.Host: Timeout value of 00:10:00 was exceeded by function: Functions.af-test-activity1.
[2023-08-24T09:21:27.001Z] Executed 'Functions.af-test-activity1' (Failed, Id=3dbab2d8-74fe-4c2c-988f-ada8621e27a0, Duration=600001ms)
[2023-08-24T09:21:27.001Z] Microsoft.Azure.WebJobs.Host: Timeout value of 00:10:00 was exceeded by function: Functions.af-test-activity1.
[2023-08-24T09:21:27.022Z] Timeout value of 00:10:00 exceeded by function 'Functions.af-test-activity1' (Id: '94ad6fdf-2f64-4d20-a3d1-21b8accb3c5a'). Initiating cancellation.
[2023-08-24T09:21:27.023Z] Executed 'Functions.af-test-activity1' (Failed, Id=94ad6fdf-2f64-4d20-a3d1-21b8accb3c5a, Duration=599995ms)
[2023-08-24T09:21:27.023Z] Microsoft.Azure.WebJobs.Host: Timeout value of 00:10:00 was exceeded by function: Functions.af-test-activity1.
[2023-08-24T09:21:27.043Z] Timeout value of 00:10:00 exceeded by function 'Functions.af-test-activity1' (Id: 'ab57533e-cd9a-491e-baa1-b0805296589b'). Initiating cancellation.
[2023-08-24T09:21:27.044Z] Executed 'Functions.af-test-activity1' (Failed, Id=ab57533e-cd9a-491e-baa1-b0805296589b, Duration=600004ms)
[2023-08-24T09:21:27.044Z] Microsoft.Azure.WebJobs.Host: Timeout value of 00:10:00 was exceeded by function: Functions.af-test-activity1.
[2023-08-24T09:21:27.054Z] Timeout value of 00:10:00 exceeded by function 'Functions.af-test-activity1' (Id: 'aff7d2ab-b99e-4ca4-9f13-d0e22d7d6dc7'). Initiating cancellation.
[2023-08-24T09:21:27.054Z] Executed 'Functions.af-test-activity1' (Failed, Id=aff7d2ab-b99e-4ca4-9f13-d0e22d7d6dc7, Duration=600001ms)
[2023-08-24T09:21:27.054Z] Microsoft.Azure.WebJobs.Host: Timeout value of 00:10:00 was exceeded by function: Functions.af-test-activity1.
[2023-08-24T09:21:27.064Z] Timeout value of 00:10:00 exceeded by function 'Functions.af-test-activity1' (Id: 'edea343e-5ee6-4f64-ab6a-f35841672c0c'). Initiating cancellation.
[2023-08-24T09:21:27.065Z] Executed 'Functions.af-test-activity1' (Failed, Id=edea343e-5ee6-4f64-ab6a-f35841672c0c, Duration=599998ms)
[2023-08-24T09:21:27.065Z] Microsoft.Azure.WebJobs.Host: Timeout value of 00:10:00 was exceeded by function: Functions.af-test-activity1.
[2023-08-24T09:21:27.084Z] Timeout value of 00:10:00 exceeded by function 'Functions.af-test-activity1' (Id: '7a69aa16-8c55-45b6-b407-04031c48d565'). Initiating cancellation.
[2023-08-24T09:21:27.085Z] Executed 'Functions.af-test-activity1' (Failed, Id=7a69aa16-8c55-45b6-b407-04031c48d565, Duration=600003ms)
[2023-08-24T09:21:27.085Z] Microsoft.Azure.WebJobs.Host: Timeout value of 00:10:00 was exceeded by function: Functions.af-test-activity1.
[2023-08-24T09:21:27.093Z] Timeout value of 00:10:00 exceeded by function 'Functions.af-test-activity1' (Id: '838e6dba-7e79-451d-9acc-9a57ebcbb8ae'). Initiating cancellation.
[2023-08-24T09:21:27.093Z] Executed 'Functions.af-test-activity1' (Failed, Id=838e6dba-7e79-451d-9acc-9a57ebcbb8ae, Duration=599996ms)
[2023-08-24T09:21:27.093Z] Microsoft.Azure.WebJobs.Host: Timeout value of 00:10:00 was exceeded by function: Functions.af-test-activity1.
[2023-08-24T09:21:27.151Z] A function timeout has occurred. Restarting worker process executing invocationId '5d051c57-208a-4d18-a837-096dcfd6c837'.
[2023-08-24T09:21:27.163Z] A function timeout has occurred. Restarting worker process executing invocationId '2fb27ec7-ba10-4f58-8837-faeafecf85c0'.
[2023-08-24T09:21:27.163Z] Restart of language worker process(es) completed.
[2023-08-24T09:21:27.166Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Function 'af-test-activity1 (Activity)' failed with an error. Reason: Microsoft.Azure.WebJobs.Host.FunctionTimeoutException: Timeout value of 00:10:00 was exceeded by function: Functions.af-test-activity1
[2023-08-24T09:21:27.166Z]    at Microsoft.Azure.WebJobs.Host.Executors.FunctionExecutor.TryHandleTimeoutAsync(Task invokeTask, CancellationToken shutdownToken, Boolean throwOnTimeout, CancellationToken timeoutToken, TimeSpan timeoutInterval, IFunctionInstance instance, Action onTimeout) in D:\a\_work\1\s\src\Microsoft.Azure.WebJobs.Host\Executors\FunctionExecutor.cs:line 669
[2023-08-24T09:21:27.166Z]    at Microsoft.Azure.WebJobs.Host.Executors.FunctionExecutor.InvokeWithTimeoutAsync(IFunctionInvoker invoker, ParameterHelper parameterHelper, CancellationTokenSource timeoutTokenSource, CancellationTokenSource functionCancellationTokenSource, Boolean throwOnTimeout, TimeSpan timerInterval, IFunctionInstance instance) in D:\a\_work\1\s\src\Microsoft.Azure.WebJobs.Host\Executors\FunctionExecutor.cs:line 584
[2023-08-24T09:21:27.166Z]    at Microsoft.Azure.WebJobs.Host.Executors.FunctionExecutor.ExecuteWithWatchersAsync(IFunctionInstanceEx instance, ParameterHelper parameterHelper, ILogger logger, CancellationTokenSource functionCancellationTokenSource) in D:\a\_work\1\s\src\Microsoft.Azure.WebJobs.Host\Executors\FunctionExecutor.cs:line 551
[2023-08-24T09:21:27.166Z]    at Microsoft.Azure.WebJobs.Host.Executors.FunctionExecutor.ExecuteWithLoggingAsync(IFunctionInstanceEx instance, FunctionStartedMessage message, FunctionInstanceLogEntry instanceLogEntry, ParameterHelper parameterHelper, ILogger logger, CancellationToken cancellationToken) in D:\a\_work\1\s\src\Microsoft.Azure.WebJobs.Host\Executors\FunctionExecutor.cs:line 368
[2023-08-24T09:21:27.166Z]    at Microsoft.Azure.WebJobs.Host.Executors.FunctionExecutor.ExecuteWithLoggingAsync(IFunctionInstanceEx instance, FunctionStartedMessage message, FunctionInstanceLogEntry instanceLogEntry, ParameterHelper parameterHelper, ILogger logger, CancellationToken cancellationToken) in D:\a\_work\1\s\src\Microsoft.Azure.WebJobs.Host\Executors\FunctionExecutor.cs:line 368
[2023-08-24T09:21:27.166Z]    at Microsoft.Azure.WebJobs.Host.Executors.FunctionExecutor.TryExecuteAsync(IFunctionInstance functionInstance, CancellationToken cancellationToken) in D:\a\_work\1\s\src\Microsoft.Azure.WebJobs.Host\Executors\FunctionExecutor.cs:line 158. IsReplay: False. State: Failed. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.3. SequenceNumber: 124. TaskEventId: 198
[2023-08-24T09:21:27.173Z] A function timeout has occurred. Restarting worker process executing invocationId '9fb81255-a989-4fa8-8ef1-16d7d07c1ee2'.
[2023-08-24T09:21:27.174Z] Restart of language worker process(es) completed.
[2023-08-24T09:21:27.174Z] 669b9777-d6af-4040-bb63-64f7bb557af9: Function 'af-test-activity1 (Activity)' failed with an error. Reason: Microsoft.Azure.WebJobs.Host.FunctionTimeoutException: Timeout value of 00:10:00 was exceeded by function: Functions.af-test-activity1
[2023-08-24T09:21:27.174Z]    at Microsoft.Azure.WebJobs.Host.Executors.FunctionExecutor.TryHandleTimeoutAsync(Task invokeTask, CancellationToken shutdownToken, Boolean throwOnTimeout, CancellationToken timeoutToken, TimeSpan timeoutInterval, IFunctionInstance instance, Action onTimeout) in D:\a\_work\1\s\src\Microsoft.Azure.WebJobs.Host\Executors\FunctionExecutor.cs:line 669
[2023-08-24T09:21:27.174Z]    at Microsoft.Azure.WebJobs.Host.Executors.FunctionExecutor.InvokeWithTimeoutAsync(IFunctionInvoker invoker, ParameterHelper parameterHelper, CancellationTokenSource timeoutTokenSource, CancellationTokenSource functionCancellationTokenSource, Boolean throwOnTimeout, TimeSpan timerInterval, IFunctionInstance instance) in D:\a\_work\1\s\src\Microsoft.Azure.WebJobs.Host\Executors\FunctionExecutor.cs:line 584
[2023-08-24T09:21:27.174Z]    at Microsoft.Azure.WebJobs.Host.Executors.FunctionExecutor.ExecuteWithWatchersAsync(IFunctionInstanceEx instance, ParameterHelper parameterHelper, ILogger logger, CancellationTokenSource functionCancellationTokenSource) in D:\a\_work\1\s\src\Microsoft.Azure.WebJobs.Host\Executors\FunctionExecutor.cs:line 551
[2023-08-24T09:21:27.174Z]    at Microsoft.Azure.WebJobs.Host.Executors.FunctionExecutor.ExecuteWithLoggingAsync(IFunctionInstanceEx instance, FunctionStartedMessage message, FunctionInstanceLogEntry instanceLogEntry, ParameterHelper parameterHelper, ILogger logger, CancellationToken cancellationToken) in D:\a\_work\1\s\src\Microsoft.Azure.WebJobs.Host\Executors\FunctionExecutor.cs:line 368
[2023-08-24T09:21:27.174Z]    at Microsoft.Azure.WebJobs.Host.Executors.FunctionExecutor.ExecuteWithLoggingAsync(IFunctionInstanceEx instance, FunctionStartedMessage message, FunctionInstanceLogEntry instanceLogEntry, ParameterHelper parameterHelper, ILogger logger, CancellationToken cancellationToken) in D:\a\_work\1\s\src\Microsoft.Azure.WebJobs.Host\Executors\FunctionExecutor.cs:line 368
[2023-08-24T09:21:27.174Z]    at Microsoft.Azure.WebJobs.Host.Executors.FunctionExecutor.TryExecuteAsync(IFunctionInstance functionInstance, CancellationToken cancellationToken) in D:\a\_work\1\s\src\Microsoft.Azure.WebJobs.Host\Executors\FunctionExecutor.cs:line 158. IsReplay: False. State: Failed. HubName: ldevtest. AppName: . SlotName: . ExtensionVersion: 2.9.3. SequenceNumber: 125. TaskEventId: 30

Restart the function again = rinse repeat. There is nothing showing in the functions monitor and inspecting the storage account the history and instances tables contain nothing too. If quick enough refreshing the control-00 queue shows this:

But that too disappears almost immediately. I appear to be in an endless loop with above :confused:. Will likely trash the storage account and function and start again but this is less than ideal if used in real world.

davidmrdavid commented 1 year ago

Thanks for the detailed info as always, I will try to reproduce this later this week.

davidmrdavid commented 1 year ago

Hi @ruankr: I cloned your repo and tried to run it, but it appears to have a fair bit of dependencies so I'm not able to easily run it just yet. It appears to connect to servicebus, and some azure infrastructure that I haven't fully figured out.

Is it realistic to get a list of instructions on what azure resources I need to set up to get this running? Trying to figure out if I can easily get this running on my machine, or if the code is just for reference but not expected to be readily executed on my machine. Please let me know

davidmrdavid commented 1 year ago

In the meantime, I'll be setting up some stress tests on my machine: I'll see if I can get this to repro by fanning over 400 activities on my machine or something like that.

davidmrdavid commented 1 year ago

@ruankr: I think I got it to reproduce. I set up a simple fan-out orchestrator that schedules 400 activities in parallel. At first, those activities were simple "Hello World" activities. With those, the orchestrator never got stuck.

However, I then made those activities call Start-Sleep, like in your repro, and suddenly the orchestrator started timing out. I need to think about what this means, but I was able to repro this locally.

Quick question: do you see this timeout behavior with the old SDK as well? My hunch would be that this reproduces in the old SDK as well.

davidmrdavid commented 1 year ago

Yeah I'm able to repro this semi consistently. According to my logs, the "stuckness" is occurring only when at least 1 of the activities errors out and it occurs when we're trying to collect the results of each of activities one by one (using the sample code to collect all outputs earlier in this thread). At some point, we call Get-DurableTaskResult and simply do not return. I'll add more traces to get to the bottom of this.

davidmrdavid commented 1 year ago

I think I have a fix here: https://github.com/Azure/azure-functions-durable-powershell/pull/68 Looking to get this reviewed and released to see if it mitigates the issue on your end :) . Might take a few more days to get it merged and out.

ruankrTs commented 12 months ago

Oh wow that's wonderful thanks for that @davidmrdavid . Would there be any code changes in the orchestrator function my end once that's in as well or should it just work? Do I still need to worry about needing to do error handling in the orchestrator function as a result or are we saying that it should be good once that change goes in?

davidmrdavid commented 12 months ago

@ruankr: If the fix works as designed, there should be no need for error handling on your end, so it should just work with your code as-is. The problem with this issue is that it was caused by low level deadlock which the user code has no control over.

The PR above was just merged (which accidentally closed this issue), so I'm preparing a release right now.

davidmrdavid commented 12 months ago

@ruankr: Can you please try to repro with version 1.0.2 of the SDK? https://github.com/Azure/azure-functions-durable-powershell/releases/tag/v1.0.2

ruankrTs commented 6 months ago

@davidmrdavid Apologies for the lack of response. I am happy to confirm though, I've been running multiple functions with a fair deal of success at least. I have found though that context switching between Azure (different tenants) and/or MsGraph seems to produce mixed results, not sure if this ever came up or if there is a recommended way to achieve good results here? I've tried with managed identity, certificates and service principals and get the same behaviour. The functions I have mainly uses service principals though (Client Credential Flow).

It will sometimes fail loading modules, because of the dll's being in use already, or the context doesn't switch because the modules aren't loaded, or it just don't connect at all, and then complaining about resources not found as its in the wrong tenant or not authenticated. I tried handling this with Start-Threadjob but it's very difficult getting a clean response or good logging doing that. Strangely it seems modules are loaded each time As per the documentation, I have specific versions of modules I use so have the import-module statement in the profile.ps1, but it appears this performs a module import at every run, even when using an always on dedicated plan, and single http triggered functions. This also slows down execution times quite a bit, and is then also what sometimes causes the module issues as they are already loaded and then complain about locked dll's, or not loaded and then complain about that. (This is easily reproducible by simply loading the MsGraph module, which seems to always have a barny with the Az.Authentication module or vice versa). So, still not perfect but at least the function/orchestrator is now handling the failures the way I wanted it to so big thanks for your help!

Azure / azure-functions-durable-powershell