azure-functions-durable-python: Orchestrations stuck in running state

@scherand, we have found this is a race condition if a crash happens during the last replay of an orchestration between updating the orchestration history and updating the state table. We have filed an issue here: https://github.com/Azure/durabletask/issues/561.

This bug has been around for a couple of years, so I am surprised we haven’t seen it until now. I’m presuming it is incredibly rare, but we will make sure to fix this for our next Durable Functions extension release.

Great! In that case, it appears to me that we’ve fixed the issue originally described in this thread 😃 . As Connor mentioned, the final issue you’re seeing is now being tracked in another thread, and we’ll look to patch it as soon as possible.

I’ll be closing this thread for now, but do feel free to re-open it if the original issue re-occurs. Thank you for your collaboration and patience with us throughout this process, we’ve fixed some major correctness concerns in the process of investigating this incident, so this was really productive on our end, thank you and reach out again if you need anything!

Hi @davidmrdavid

Thanks heaps for following up with the questions about reverting the change and GitHub Actions for deployment. Sounds great to me 😃.

I agree about the warnings: since they are gone and I did not run into any issues yet I assume all is good. I need to better understand the build process at some point, that might provide additional clues. Somehow it seems that the build process (oryx?) is using a different environment (venv?) than the one configured in VS Code. For a long time (I belive before I even opened this issue) it is reporting that a newer version of pip is available even though the newest version is installed in the venv used by VSCode.

From the Python shell in VS Code:

(.venv) PS C:\Users\...> pip --version
pip 21.1.3 from c:\users\...\.venv\lib\site-packages\pip (python 3.8)

From the build process:

...: WARNING: You are using pip version 20.2.3; however, version 21.1.3 is available.
...: You should consider upgrading via the '/tmp/oryx/platforms/python/3.8.6/bin/python3.8 -m pip install --upgrade pip' command.

Now for the fun part 😃:

This is about the “stuck” orchestration 458aa5e1e7b04f0096ac072d251f4f89 again. It is correct that I believe the execution actually succeeded. I deduct this from the entries in the history table of the durable function. Mainly the two entries stating “ExecutionCompleted” and “OrchestratorCompleted”.

And it is also true that the information in Application Insights does not seem to reflect everything from the history table. Mainly I only see twelve calls to CalculationCleanup instead of the expected 25.

BUT, and that seems to be a bit more serious, when calling the statusQueryGetUri (the one like https://...azurewebsites.net/runtime/webhooks/durabletask/instances/458aa5e1e7b04f0096ac072d251f4f89?taskHub=...&connection=Storage&code=0e...w==) it comes back with a runtimeStatus of Running. So client code assumes the function is not done (yet). At the end of the day I do not know if this is “just” related to a failing propagation of information to Application Insights or if this is an issue on its own.

Cheers

Hi @davidmrdavid

Thank you so much for the update and the detailed instructions. I will look into this as soon as I can. I might have to wait a couple of days though before I can run another batch of calculations. I will update this issue as soon as I had a chance to tackle this.

Hi @davidmrdavid

Thanks heaps for this update! These are exciting news. Of course I do hope that the bug(s) fixed were the root cause for the issue we experienced. But I can only guess the complexity of the system and understand that only testing will definitely determine this.

For now, let me tell you that I am very impressed with the support you guys provide. The effort and transparency are exceptional. I would not have dreamed this when I created this issue. Keep that spirit up!

Looking forward to hearing from you again.

Hi @scherand!

Great to hear that Application Insights is enabled, that’s half the battle! My understanding is that logging to Application Insights from a Python application requires just a tad more setup. There might be an easier way to do this, but let me give you my way and hopefully that’s enough to fast-track us towards getting this runtime data.

So we’re going to follow the general setup outlined here. In particular, you’ll want to:

(1) Install the OpenCensus handler for Azure Functions. To do this, please add the following dependency to your requirements.txt

opencensus-ext-azure

As an example, my full requirements.txt when I was reproducing this issue looks like:

azure-functions
azure-functions-durable
opencensus-ext-azure

(2) Next, we’ll set-up the OpenCensus handler in your orchestrator file. You just need to add the following import statement

from opencensus.ext.azure.log_exporter import AzureLogHandler

and then provide your Application Insights InstrumentationKey to this snippet right here:

logger_opencensus = logging.getLogger('opencensus')
logger_opencensus.addHandler(
    AzureLogHandler(
        connection_string='InstrumentationKey=<the rest of your key here>'
    )
)

# the key has the following format: InstrumentationKey=<something>;IngestionEndpoint=<something>
# you can find it on the top-level banner when you access your Application Insights resource in the Azure portal

So, for example, the top of your orchestrator file might now look as follows

import logging
import json

import azure.functions as func
import azure.durable_functions as df
from opencensus.ext.azure.log_exporter import AzureLogHandler

logger_opencensus = logging.getLogger('opencensus')
logger_opencensus.addHandler(
    AzureLogHandler(
        connection_string='<the key>'
    )
)

def orchestrator_function(context: df.DurableOrchestrationContext):

(3) Now we can start logging! The API looks as follows:

logger_opencensus.info('your message here!')

So a simple orchestrator that logs to Application Insights might look like:

def orchestrator_function(context: df.DurableOrchestrationContext):
    if not context.is_replaying:
        logger_opencensus.info('my_debug_category hi there!')
    result1 = yield context.call_activity('Hello', "Tokyo")
    result2 = yield context.call_activity('Hello', "Seattle")
    result3 = yield context.call_activity('Hello', "London")
    return [result1, result2, result3]

(4) Now we can find your logs by going to your Application Insights resource in the Azure portal, then to the Logs option, and finally writing a query that looks like this:

traces
| where * contains "<a prefix of your log>"

So in the example above, I would query for:

traces
| where * contains "my_debug_category"

I’m attaching a picture of what your output should roughly look like. See below:

And that’s about it!

Try this out with a simple test orchestration and let us know if you’re able to locate your own logs in Application Insights. Afterwards, we can make your logs be more granular by including, in the prefix, the instanceID of your orchestration. You can access this value via context._instance_id. With that, we should have enough to find the data we’re looking for! Please let me know if anything about this was unclear, I realize this comment is rather long by now ⚡ . Thanks!

@davidmrdavid, it’s a bit hard to tell, but it appears that a failure in the fan-out call_actvity_with_retry created something weird with the Python implementation. We may want to see if we can repro this ourselves.

@pcopley, each of these stuck orchestration bugs can have fairly independent root causes, so I would recommend opening a separate ticket for your issue.