Completed event not raised with Event Grid

[przemos]

Describe the bug
A simple orchestrator delegating the work to 2 activities (one w/o async/await - returns immediately, the other w/) and then awaited with yield completes successfully - the status of orchestration is marked as Completed, but the Completed event is not raised with EventGrid. Only Started event is raised.

Investigative information

• Durable Functions extension version:
  "extensionBundle": {
  "id": "Microsoft.Azure.Functions.ExtensionBundle",
  "version": "[2.*, 3.0.0)"
  }
• durable-functions npm module version:
  "durable-functions": "^1.5.3",
• Language (JavaScript/TypeScript) and version: Javascript
• Node.js version: v14.17.3

Testing locally.

To Reproduce
Steps to reproduce the behavior:

1. Prepare an orchestrator client, orchestrator and activity
   2.Orchestrator

const df = require("durable-functions");

module.exports = df.orchestrator(function* (context) {
    const outputs = [];
    outputs.push(context.df.callActivity("TaskA", "This does NOT contain async/await"));
    outputs.push(context.df.callActivity("TaskB", "This contains async/await"));
    results = yield context.df.Task.all(outputs);
});

3. TaskA

module.exports = async function (context) {

    return `Hello ${context.bindings.name}!`;
};

4. TaskB

require('got')
module.exports = async function (context) {

    const response = await got('https://google.com');
    console.log(`Hello I am finished:` + response.statusCode);

    return `Hello ${context.bindings.name}!`;
};

Expected behavior
Durable Functions framework fires Completed event just as it sends Started event:
07200c19afa245f2bfdeccc5d4289507: Function 'DurableFunctionsOrchestrator (Orchestrator)' sent a 'Started' notification event to Azure Event Grid. Status code: 200. Details: . HubName: CustomHub. AppName: . SlotName: . ExtensionVersion: 2.5.1. SequenceNumber: 8. Latency: 477 ms.

Actual behavior
The orchestration completes correctly - the status of the orchestration is marked as completed. The Completed event is never raised with EventGrid.
The last log statements are:

[2021-11-27T12:29:35.148Z] Executed 'Functions.TaskB' (Succeeded, Id=d01f9171-62ce-4968-ab99-96169ea1fbc3, Duration=847ms)
[2021-11-27T12:29:35.149Z] b6829443aa3d4bd8b576a33f1eac0bd3: Function 'TaskB (Activity)' completed. ContinuedAsNew: False. IsReplay: False. Output: (136 bytes). State: Completed. HubName: CustomHub. AppName: . SlotName: . ExtensionVersion: 2.5.1. SequenceNumber: 13. TaskEventId: 1
[2021-11-27T12:29:35.486Z] Executing 'Functions.DurableFunctionsOrchestrator' (Reason='(null)', Id=3dbb4e55-5fc1-4ba0-b972-7768dc7e400d)
[2021-11-27T12:29:35.496Z] Executed 'Functions.DurableFunctionsOrchestrator' (Succeeded, Id=3dbb4e55-5fc1-4ba0-b972-7768dc7e400d, Duration=10ms)

Screenshots
If applicable, add screenshots to help explain your problem.

Known workarounds
Provide a description of any known workarounds you used.

Additional context
Host.json

{
  "version": "2.0",
  "logging": {
    "logLevel": {
      "Host.Triggers.DurableTask": "Debug"
    }
},
    "extensions": {
        "durableTask": {
          "hubName": "CustomHub",
          "notifications": {
            "eventGrid": {
              "topicEndpoint": "https://<grid>.uksouth-1.eventgrid.azure.net/api/events",
              "keySettingName": "EventGridKey",
              "publishEventTypes": [
                "Started",
                "Completed",
                "Terminated"
              ]
            }
          }
        }
      },
  "extensionBundle": {
    "id": "Microsoft.Azure.Functions.ExtensionBundle",
    "version": "[2.*, 3.0.0)"
  }
}

• Development environment (ex. Visual Studio)

Azure Functions Core Tools
Core Tools Version: 3.0.3904 Commit hash: c345f7140a8f968c5dbc621f8a8374d8e3234206 (64-bit)
Function Runtime Version: 3.3.1.0

[przemos]

Failed orchestration event is being raised correctly, though:

{
  id: 'e45654a7-757b-4f88-aad1-22d4f0fbad2c',
  subject: 'durable/orchestrator/Failed',
  data: {
     hubName: 'CustomHub',
     functionName: 'DurableFunctionsOrchestrator',
     instanceId: '644f7b6d305b4416820dee869be58f4b',
     reason: 'Message: context.df.Task.all() encountered the below error messages:',
     runtimeStatus: 'Failed'
  },
  eventType: 'orchestratorEvent',
  dataVersion: '1.0',
  metadataVersion: '1',
   eventTime: '2021-11-28T10:26:20.343227Z',
  topic: '<redacted>'
 }

When suborchestrator is called and it fails with an error (as simple as throw new Error('an error')), the events that are sent for the suborchestrator are Started and Failed. When the error propagates to the parent orchestrator which fails (the error is rethrown as a result of context.df.Task.all() on the suborchestrator task), the event for the parent orchestrator is not emitted - neither Completed nor Failed.

Confirming the behaviour is the same in the cloud.

[cgillum]

Hi @przemos, your observation about the sub-orchestrator is interesting. Were you able to see a Completed event raised in the case where the sub-orchestrator completed successfully?

I did a walkthrough of the code which manages the sending of notifications and nothing stood out to me that might explain this behavior. I think we'll need to try to reproduce this on our side to understand what might be happening.

[przemos]

Hi @przemos, your observation about the sub-orchestrator is interesting. Were you able to see a Completed event raised in the case where the sub-orchestrator completed successfully?

I did a walkthrough of the code which manages the sending of notifications and nothing stood out to me that might explain this behavior. I think we'll need to try to reproduce this on our side to understand what might be happening.

Hi, yes, I can see it but only for the sub-orchestrator:
[2021-12-07T13:29:00.029Z] d887479f4af1404ba5d7ce39521aa3fd:1: Function 'SubOrchestrator (Orchestrator)' sent a 'Completed' notification event to Azure Event Grid. Status code: 200. Details: . HubName: someHub. AppName: . SlotName: . ExtensionVersion: 2.5.1. SequenceNumber: 17. Latency: 105 ms.

[davidmrdavid]

Hi @przemos, I noticed you recently reviewed this issue.

Please let me know if you continue seeing this issue with the SDK (and extension) versions listed as a workaround in that issue. If you do, then could you please attach a .zip'ed reproducer of this issue? I tried getting this to work from the code snippets you shared but I was getting some issues with the got package. If possible, it would be ideal to reproduce this with no external dependencies beyond durable-functions, so I'd appreciate if the reproducer could be as barebones as possible. Thanks!

[przemos]

durable.zip
Checked with 1.5.4 durable-functions package and DurableTask extension 2.6. I get a completed event when run first time, but subsequent runs do not yield it. Please make sure the config points to a valid storage account and event grid key is set.

[davidmrdavid]

Thanks, @przemos. I've tagged this as help wanted to make sure we discuss it in our NodeJS sync this coming Monday.