Azure / azure-functions-durable-js

JavaScript library for using the Durable Functions bindings
https://www.npmjs.com/package/durable-functions
MIT License
129 stars 47 forks source link

Completed event not raised with Event Grid #297

Open przemos opened 2 years ago

przemos commented 2 years ago

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

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://.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 commented 2 years ago

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 commented 2 years ago

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 commented 2 years ago

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 commented 2 years ago

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 commented 2 years ago

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 commented 2 years ago

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