search

slackapi / deno-slack-sdk

SDK for building Run on Slack apps using Deno
https://api.slack.com/automation
MIT License
166 stars 27 forks source link

error: event_dispatch_failed when function takes more than 3 seconds to complete in local run #179

Closed tomas-zijdemans-vipps closed 7 months ago

tomas-zijdemans-vipps commented 1 year ago

So I've been writing quite a lot of functions and I've noticed that I randomly get this error (it will appear on one execution of a function, but not the next time the same function is called).

I've now added a new function that retrieves data from Salesforce, which takes a few seconds - and this seems to consistently trigger the error. The workflow works, so this is not critical. However, seems like something that should be fixed. Here is my activity log with verbose mode:

2023-05-29 23:14:25 [info] [Wf055UPWNPR8] (Trace=Tr059WAYQX8V) Workflow 'Partner Report' started
2023-05-29 23:14:26 [info] [Wf055UPWNPR8] (Trace=Tr059WAYQX8V) Workflow step 1 of 6 started
2023-05-29 23:14:27 [info] [Fn055E7UTCF9] (Trace=Tr059WAYQX8V) Function 'Get Splunk Results' (app function) started
2023-05-29 23:14:29 [info] [Fn055E7UTCF9] (Trace=Tr059WAYQX8V) Function 'Get Splunk Results' (app function) completed
2023-05-29 23:14:30 [info] [Wf055UPWNPR8] (Trace=Tr059WAYQX8V) Workflow step 'Get Splunk Results' completed
2023-05-29 23:14:31 [info] [Wf055UPWNPR8] (Trace=Tr059WAYQX8V) Workflow step 2 of 6 started
[2023-05-29 21:14:14] received: {"envelope_id":"15023d08-2235-4235-9ffd-f9c5e34814e4","payload":{"token":"redacted","team_id":"redacted","api_app_id":"redacted","event":{"type":"function_executed","function":{"id":"Fn059G3PKYC8","callback_id":"get-partner-data","title":"Get Partner data","description":"","type":"app","input_parameters":[],"output_parameters":[{"type":"array","name":"partners","description":"Array of Partners","title":"Partners","is_required":true,"items":{"type":"#\/types\/PartnerContactDetailsData"}}],"app_id":"redacted","date_created":1684694968,"date_updated":1685394857,"date_deleted":0},"inputs":{},"function_execution_id":"Fx05AP0J7MPS","workflow_execution_id":"Wx059SLRUD7Y","event_ts":"1685394872.882344","bot_access_token":"redacted"},"type":"event_callback","event_id":"Ev05AP0J8WJC","event_time":1685394872},"type":"events_api","accepts_response_payload":false,"retry_attempt":0,"retry_reason":""}
2023-05-29 23:14:32 [info] [Fn059G3PKYC8] (Trace=Tr059WAYQX8V) Function 'Get Partner data' (app function) started
Partners retrieved from Salesforce
2023-05-29 23:14:36 [info] [Fn059G3PKYC8] (Trace=Tr059WAYQX8V) Function 'Get Partner data' (app function) completed
2023-05-29 23:14:36 [error] [Fn059G3PKYC8] (Trace=Tr059WAYQX8V) Function 'Get Partner data' (app function) failed
        event_dispatch_failed
2023-05-29 23:14:37 [info] [Wf055UPWNPR8] (Trace=Tr059WAYQX8V) Workflow step 'Get Partner data' completed
filmaj commented 1 year ago

Hey @tomas-zijdemans-vipps , thanks for reporting this.

I dug around a bit in our backend and was able to find the workflow/function execution related to the activity logs you posted. (posting the received: { json payload } was really helpful to extract the workflow and function execution IDs - thank you!)

It seems to me that some manner of network disconnect issue causes an underlying error in our backend that looks like:

upstream connect error or disconnect/reset before headers. reset reason: remote reset

It's interesting because I see a successful, HTTP 200 OK returned response to the functions.completeSuccess API (this is called by the SDK and on deployed applications under-the-hood when your custom function completes successfully) in the backend logs, initiated by your application. This, at least, explains why the workflow completes successfully.

Can you explain to me what you did to exacerbate the issue? You said after adding a new function, that takes a few seconds, you can regularly trip this error. Can you elaborate on that? You added a new function to your existing workflow, or you made a new function call within your existing custom function? Did you add it before or after the function that ends up raising the event_dispatch_failed error? Any details there is helpful to us and I appreciate you taking the time 🙏

filmaj commented 1 year ago

One more question @tomas-zijdemans-vipps: can you confirm whether this was for a deployed application or for a local-run application? And does the event_dispatch_failed error occur, from your perspective, as frequently in both contexts, or more so in one vs. the other?

tomas-zijdemans-vipps commented 1 year ago

Thanks for answering.

I can recreate it now very easily (sorry for not answering your questions above, but I think this information might be more useful).

Here is what I did:

  1. Install the sample "Reverse String" (slack create reverse-string-app -t slack-samples/deno-reverse-string)
  2. Add 1 line of code in the reverse.ts function (I added it as the first line, line 37): setTimeout(() => { console.log('hello'); }, 1000);
  3. Execute slack run
  4. Trigger the function 3 times

Result: No errors

  1. Stopped the application
  2. Changed the timeout from 1000 milliseconds to 3000 milliseconds in the above line
  3. Execute slack run
  4. Trigger the function 3 times

Result: The error is logged every time

Log:

Connected, awaiting events
[2023-05-31 07:27:17] received: {"type":"hello","num_connections":1,"debug_info":{"host":"applink-1","build_number":30,"approximate_connection_time":18060},"connection_info":{"app_id":"A059TEP2K63"}}
2023-05-31 09:27:28 [info] [Fn05A52R4F2R] (Trace=Tr05AXNQFTEC) Function 'Test Reverse Function' (workflow function) started
2023-05-31 09:27:28 [info] [Wf05A817HBQS] (Trace=Tr05AXNQFTEC) Workflow 'Test Reverse Function' started
2023-05-31 09:27:29 [info] [Wf05A817HBQS] (Trace=Tr05AXNQFTEC) Workflow step 1 of 3 started
2023-05-31 09:27:29 [info] [Fn010N] (Trace=Tr05AXNQFTEC) Function 'Open a form' (Slack function) started
2023-05-31 09:27:32 [info] [Fn010N] (Trace=Tr05AXNQFTEC) Function 'Open a form' (Slack function) completed
[2023-05-31 07:27:17] received: {"envelope_id":"1b04e052-47b8-4048-8d8a-d69ea6fdb4cb","payload":{"token":"redacted","team_id":"redacted","api_app_id":"A059TEP2K63","event":{"type":"function_executed","function":{"id":"Fn05AADSDQDA","callback_id":"reverse","title":"Reverse","description":"Takes a string and reverses it","type":"app","input_parameters":[{"type":"string","name":"stringToReverse","description":"The string to reverse","title":"String To Reverse","is_required":true}],"output_parameters":[{"type":"string","name":"reversedString","description":"The string in reverse","title":"Reversed String","is_required":true}],"app_id":"A059TEP2K63","date_created":1685517633,"date_updated":1685518040,"date_deleted":0},"inputs":{"stringToReverse":"sdfg"},"function_execution_id":"Fx05ALLSEW01","workflow_execution_id":"Wx059TFPM66B","event_ts":"1685518055.744476","bot_access_token":"redacted"},"type":"event_callback","event_id":"Ev05ALLSJJ01","event_time":1685518055},"type":"events_api","accepts_response_payload":false,"retry_attempt":0,"retry_reason":""}
2023-05-31 09:27:32 [info] [Wf05A817HBQS] (Trace=Tr05AXNQFTEC) Workflow step 'Open a form' completed
2023-05-31 09:27:34 [info] [Wf05A817HBQS] (Trace=Tr05AXNQFTEC) Workflow step 2 of 3 started
2023-05-31 09:27:35 [info] [Fn05AADSDQDA] (Trace=Tr05AXNQFTEC) Function 'Reverse' (app function) started
hello
2023-05-31 09:27:36 [info] [Fn05AADSDQDA] (Trace=Tr05AXNQFTEC) Function 'Reverse' (app function) completed
2023-05-31 09:27:38 [info] [Wf05A817HBQS] (Trace=Tr05AXNQFTEC) Workflow step 'Reverse' completed
2023-05-31 09:27:39 [error] [Fn05AADSDQDA] (Trace=Tr05AXNQFTEC) Function 'Reverse' (app function) failed
        event_dispatch_failed
2023-05-31 09:27:39 [info] [Wf05A817HBQS] (Trace=Tr05AXNQFTEC) Workflow step 3 of 3 started
2023-05-31 09:27:40 [info] [Fn0102] (Trace=Tr05AXNQFTEC) Function 'Send a message to channel' (Slack function) started
2023-05-31 09:27:42 [info] [Fn0102] (Trace=Tr05AXNQFTEC) Function 'Send a message to channel' (Slack function) completed
2023-05-31 09:27:43 [info] [Wf05A817HBQS] (Trace=Tr05AXNQFTEC) Workflow step 'Send a message to channel' completed
2023-05-31 09:27:44 [info] [Fn05A52R4F2R] (Trace=Tr05ALLT9ZL1) Function 'Test Reverse Function' (workflow function) started
2023-05-31 09:27:44 [info] [Wf05A817HBQS] (Trace=Tr05ALLT9ZL1) Workflow 'Test Reverse Function' started
2023-05-31 09:27:44 [info] [Fn05A52R4F2R] (Trace=Tr05AXNQFTEC) Function 'Test Reverse Function' (workflow function) completed
2023-05-31 09:27:44 [info] [Wf05A817HBQS] (Trace=Tr05AXNQFTEC) Workflow 'Test Reverse Function' completed
2023-05-31 09:27:46 [info] [Wf05A817HBQS] (Trace=Tr05ALLT9ZL1) Workflow step 1 of 3 started
2023-05-31 09:27:46 [info] [Fn010N] (Trace=Tr05ALLT9ZL1) Function 'Open a form' (Slack function) started
2023-05-31 09:27:48 [info] [Fn010N] (Trace=Tr05ALLT9ZL1) Function 'Open a form' (Slack function) completed
[2023-05-31 07:27:17] received: {"envelope_id":"c8b666fd-c648-4c9a-a07c-b3dbb0509cf6","payload":{"token":"redacted","team_id":"redacted","api_app_id":"A059TEP2K63","event":{"type":"function_executed","function":{"id":"Fn05AADSDQDA","callback_id":"reverse","title":"Reverse","description":"Takes a string and reverses it","type":"app","input_parameters":[{"type":"string","name":"stringToReverse","description":"The string to reverse","title":"String To Reverse","is_required":true}],"output_parameters":[{"type":"string","name":"reversedString","description":"The string in reverse","title":"Reversed String","is_required":true}],"app_id":"A059TEP2K63","date_created":1685517633,"date_updated":1685518040,"date_deleted":0},"inputs":{"stringToReverse":"asdf"},"function_execution_id":"Fx059TFRH5JB","workflow_execution_id":"Wx05A829GZ18","event_ts":"1685518071.568873","bot_access_token":"redacted"},"type":"event_callback","event_id":"Ev05ALLU09MX","event_time":1685518071},"type":"events_api","accepts_response_payload":false,"retry_attempt":0,"retry_reason":""}
2023-05-31 09:27:49 [info] [Wf05A817HBQS] (Trace=Tr05ALLT9ZL1) Workflow step 'Open a form' completed
2023-05-31 09:27:50 [info] [Wf05A817HBQS] (Trace=Tr05ALLT9ZL1) Workflow step 2 of 3 started
2023-05-31 09:27:51 [info] [Fn05AADSDQDA] (Trace=Tr05ALLT9ZL1) Function 'Reverse' (app function) started
hello
2023-05-31 09:27:52 [info] [Fn05AADSDQDA] (Trace=Tr05ALLT9ZL1) Function 'Reverse' (app function) completed
2023-05-31 09:27:53 [info] [Wf05A817HBQS] (Trace=Tr05ALLT9ZL1) Workflow step 'Reverse' completed
2023-05-31 09:27:55 [error] [Fn05AADSDQDA] (Trace=Tr05ALLT9ZL1) Function 'Reverse' (app function) failed
        event_dispatch_failed
2023-05-31 09:27:55 [info] [Wf05A817HBQS] (Trace=Tr05ALLT9ZL1) Workflow step 3 of 3 started
2023-05-31 09:27:55 [info] [Fn0102] (Trace=Tr05ALLT9ZL1) Function 'Send a message to channel' (Slack function) started
2023-05-31 09:27:58 [info] [Fn0102] (Trace=Tr05ALLT9ZL1) Function 'Send a message to channel' (Slack function) completed
2023-05-31 09:27:58 [info] [Wf05A817HBQS] (Trace=Tr05ALLT9ZL1) Workflow step 'Send a message to channel' completed
2023-05-31 09:28:00 [info] [Fn05A52R4F2R] (Trace=Tr05ALLT9ZL1) Function 'Test Reverse Function' (workflow function) completed
2023-05-31 09:28:00 [info] [Wf05A817HBQS] (Trace=Tr05ALLT9ZL1) Workflow 'Test Reverse Function' completed
2023-05-31 09:28:05 [info] [Fn05A52R4F2R] (Trace=Tr05AAEW59CL) Function 'Test Reverse Function' (workflow function) started
2023-05-31 09:28:05 [info] [Wf05A817HBQS] (Trace=Tr05AAEW59CL) Workflow 'Test Reverse Function' started
2023-05-31 09:28:06 [info] [Wf05A817HBQS] (Trace=Tr05AAEW59CL) Workflow step 1 of 3 started
2023-05-31 09:28:06 [info] [Fn010N] (Trace=Tr05AAEW59CL) Function 'Open a form' (Slack function) started
2023-05-31 09:28:09 [info] [Fn010N] (Trace=Tr05AAEW59CL) Function 'Open a form' (Slack function) completed
2023-05-31 09:28:10 [info] [Wf05A817HBQS] (Trace=Tr05AAEW59CL) Workflow step 'Open a form' completed
2023-05-31 09:28:11 [info] [Wf05A817HBQS] (Trace=Tr05AAEW59CL) Workflow step 2 of 3 started
[2023-05-31 07:27:17] received: {"envelope_id":"c00dd817-e83c-44a5-9e18-c319452d2bb1","payload":{"token":"redacted","team_id":"redacted","api_app_id":"A059TEP2K63","event":{"type":"function_executed","function":{"id":"Fn05AADSDQDA","callback_id":"reverse","title":"Reverse","description":"Takes a string and reverses it","type":"app","input_parameters":[{"type":"string","name":"stringToReverse","description":"The string to reverse","title":"String To Reverse","is_required":true}],"output_parameters":[{"type":"string","name":"reversedString","description":"The string in reverse","title":"Reversed String","is_required":true}],"app_id":"A059TEP2K63","date_created":1685517633,"date_updated":1685518040,"date_deleted":0},"inputs":{"stringToReverse":"asdf"},"function_execution_id":"Fx05AXNU3XGQ","workflow_execution_id":"Wx05AXNTLPPA","event_ts":"1685518092.833438","bot_access_token":"redacted"},"type":"event_callback","event_id":"Ev05A53VD64V","event_time":1685518092},"type":"events_api","accepts_response_payload":false,"retry_attempt":0,"retry_reason":""}
2023-05-31 09:28:12 [info] [Fn05AADSDQDA] (Trace=Tr05AAEW59CL) Function 'Reverse' (app function) started
2023-05-31 09:28:14 [info] [Fn05AADSDQDA] (Trace=Tr05AAEW59CL) Function 'Reverse' (app function) completed
2023-05-31 09:28:15 [info] [Wf05A817HBQS] (Trace=Tr05AAEW59CL) Workflow step 'Reverse' completed
hello
2023-05-31 09:28:16 [error] [Fn05AADSDQDA] (Trace=Tr05AAEW59CL) Function 'Reverse' (app function) failed
        event_dispatch_failed
2023-05-31 09:28:16 [info] [Wf05A817HBQS] (Trace=Tr05AAEW59CL) Workflow step 3 of 3 started
2023-05-31 09:28:17 [info] [Fn0102] (Trace=Tr05AAEW59CL) Function 'Send a message to channel' (Slack function) started
2023-05-31 09:28:20 [info] [Fn0102] (Trace=Tr05AAEW59CL) Function 'Send a message to channel' (Slack function) completed
2023-05-31 09:28:21 [info] [Wf05A817HBQS] (Trace=Tr05AAEW59CL) Workflow step 'Send a message to channel' completed
2023-05-31 09:28:23 [info] [Fn05A52R4F2R] (Trace=Tr05AAEW59CL) Function 'Test Reverse Function' (workflow function) completed
2023-05-31 09:28:23 [info] [Wf05A817HBQS] (Trace=Tr05AAEW59CL) Workflow 'Test Reverse Function' completed
tomas-zijdemans-vipps commented 1 year ago

One more question @tomas-zijdemans-vipps: can you confirm whether this was for a deployed application or for a local-run application? And does the event_dispatch_failed error occur, from your perspective, as frequently in both contexts, or more so in one vs. the other?

Hi again, looking into my logs - the frequency seems to be the same for both contexts.

filmaj commented 1 year ago

Hey @tomas-zijdemans-vipps , sorry for the delay in response.

I believe the issue here is that, currently, when running functions in a local-run context, there is a hard 3 second limit to completing the function. We know this limitation is inconvenient, especially when taken into account that Run-on-Slack functions have a 15 second limit (as per #181).

We are aware of this limitation and are planning to address it. I will bring this to the attention of our team to get it prioritized to at least line up with the Run-on-Slack timeout limits.

tomas-zijdemans-vipps commented 1 year ago

Thanks! That explains it. It could be worth considering having a more descriptive error message as well.. Like "Timeout Error: Function x did not complete within the max 15sec limit"

filmaj commented 1 year ago

Update! We are slowly rolling out support for expanding locally-running functions to 15 seconds. Should be fully released within 24 hours.

tomas-zijdemans-vipps commented 1 year ago

Very nice!

markfoden commented 11 months ago

@filmaj I think I'm getting the same thing - see below

I have a function in step 1 of a workflow with two client.apiCall(conversations. ) calls that take less than a couple of seconds.

The function completes successfully but occasionally this _event_dispatchfailed error occurs. Oddly the remaining workflows seem to work anyway.

Is there a way to trap this error?

Thanks

2023-12-02 10:45:54 [info] [Fn066BHGLQ8M] (Trace=Tr068E8BTS2G) Function 'Get Deal Function' (app function) completed
2023-12-02 10:45:54 [info] [Wf066BAJ7TN1] (Trace=Tr068E8BTS2G) Workflow step 'Get Deal Function' completed
2023-12-02 10:45:54 [error] [Fn066BHGLQ8M] (Trace=Tr068E8BTS2G) Function 'Get Deal Function' (app function) failed
    event_dispatch_failed
Token fetch succeeded for user 'U4616159U' on workspace 'T460BGG6A' for app 'A066E5JGW11' and provider 'zoho'
2023-12-02 10:45:55 [info] [Wf066BAJ7TN1] (Trace=Tr068E8BTS2G) Workflow step 2 of 2 started
2023-12-02 10:45:55 [info] [Fn067382QLGG] (Trace=Tr068E8BTS2G) Function 'Allocate Modal' (app function) started
filmaj commented 11 months ago

Hey @markfoden , I created #256 to track this. FWIW I have also seen this intermittently in our end to end integration test suite, and have seen other developers mention they see these seemingly-random event_dispatch_failed errors pop up.

Let's gather info in there, and I'll start gathering backend logs and data on my end in order to start figuring out what's going on.

filmaj commented 11 months ago

That said, I can confirm, when running locally, that I will see an event_dispatch_failed error in my activity logs if my locally-running function takes longer than 3 seconds to respond. The workflow and function will still work, however.

So I think this issue related to timing out is still happening. I will follow up internally.

filmaj commented 11 months ago

Did some more digging here: indeed the event_dispatch_failed error will show up in your activity logs when both a) running locally via slack run and b) your function takes more than 3 seconds to return.

We are working internally to fix this, your patience is appreciated 🙇

filmaj commented 7 months ago

Hello everyone, great news! We've extended the local-run timeout to 15 seconds for all workspaces.

Going to close this issue but if you experience any issues related here feel free to comment, re-open and/or open a new issue.

tzuo9 commented 1 month ago

This still happens when I run locally with a api call takes sometimes over 3 seconds. I wonder is the timeout 3s or 15s now?