[BUG] 'addBlockActionsHandler' not triggered and 'event_dispatch_failed' error if constructing Ocotokit

[oeed]

The deno-slack versions deno_slack_sdk: 2.12.0 deno_slack_api: 2.4.0

Deno runtime version CLI: 2.26.0 deno: 1.44.4 typescript: 5.4.5 v8: 12.6.228.9

OS info

macOS 14.5

Describe the bug

I am building based off the 'time off approval' example and in my function I send a message with actions and addBlockActionsHandler. I am currently just running locally.

If I initialise a new Octokit the function runs fine and creates a message, but when I click one of the action buttons the handler does not get called. The spinner appears for a few seconds and the workflow evidently fails with the following logs:

2024-06-27 17:59:51 [info] [Wf079C8UQXRD] (Trace=Tr07A27QS44U) Shortcut trigger successfully started execution of function 'Request Release Approval'
2024-06-27 17:59:51 [info] [Fn079PU53U1K] (Trace=Tr07A27QS44U) Function 'Request Release Approval' (workflow function) started
2024-06-27 17:59:51 [info] [Wf079C8UQXRD] (Trace=Tr07A27QS44U) Workflow 'Request Release Approval' started
2024-06-27 17:59:52 [info] [Wf079C8UQXRD] (Trace=Tr07A27QS44U) Workflow step 1 of 1 started
2024-06-27 17:59:52 [info] [Fn079SU16U0J] (Trace=Tr07A27QS44U) Function 'Request Release Approval' (app function) started
Function invoked
Getting GitHub token
Got GitHub token
Got token
Initialised Octokit
return completed: false
2024-06-27 18:00:07 [error] [Fn079SU16U0J] (Trace=Tr07A27QS44U) Function 'Request Release Approval' (app function) failed
        event_dispatch_failed
2024-06-27 18:00:08 [error] [Wf079C8UQXRD] (Trace=Tr07A27QS44U) Workflow step 'Request Release Approval' failed
2024-06-27 18:00:08 [error] [Wf079C8UQXRD] (Trace=Tr07A27QS44U) Workflow 'Request Release Approval' failed
        Function failed to execute
2024-06-27 18:00:08 [error] [Fn079PU53U1K] (Trace=Tr07A27QS44U) Function 'Request Release Approval' (workflow function) failed
        Function failed to execute

However, if I simply comment out the Ocotokit constructor (but still leave the token async call) it works perfectly.

import { Octokit } from "https://esm.sh/octokit@4.0.2?dts"

// gitHubInstallationToken and other funcs...

export const getOctokit = async (env: Env) => {
  console.log("Getting GitHub token")
  const token = await gitHubInstallationToken(env)
  console.log("Got token")
  // const octo = new Octokit({
  //   auth: token,
  // })
  // console.log("Initialised Octokit")
  // return octo
}

2024-06-27 18:02:05 [info] [Wf079C8UQXRD] (Trace=Tr079ZPDQSH0) Shortcut trigger successfully started execution of function 'Request Release Approval'
2024-06-27 18:02:05 [info] [Fn079PU53U1K] (Trace=Tr079ZPDQSH0) Function 'Request Release Approval' (workflow function) started
2024-06-27 18:02:05 [info] [Wf079C8UQXRD] (Trace=Tr079ZPDQSH0) Workflow 'Request Release Approval' started
2024-06-27 18:02:05 [info] [Wf079C8UQXRD] (Trace=Tr079ZPDQSH0) Workflow step 1 of 1 started
2024-06-27 18:02:05 [info] [Fn079SU16U0J] (Trace=Tr079ZPDQSH0) Function 'Request Release Approval' (app function) started
Function invoked
Getting GitHub token
Got GitHub token
Got token
return completed: false
Block action handler invoked
2024-06-27 18:02:10 [info] [Fn079SU16U0J] (Trace=Tr079ZPDQSH0) Function 'Request Release Approval' (app function) completed
2024-06-27 18:02:10 [info] [Wf079C8UQXRD] (Trace=Tr079ZPDQSH0) Workflow step 'Request Release Approval' completed
2024-06-27 18:02:11 [info] [Fn079PU53U1K] (Trace=Tr079ZPDQSH0) Function 'Request Release Approval' (workflow function) completed
2024-06-27 18:02:11 [info] [Wf079C8UQXRD] (Trace=Tr079ZPDQSH0) Workflow 'Request Release Approval' completed

I get messages from Slackbot saying the workflow function failed to execute, but the log links it provides just leads to a blank page, I suspect related to #326. There aren't really any clues in slack-debug-2024xx.log either.

It's worth noting that Ocotokit does work in the initial function and I can use it to make requests, but it's mere presence seems to kill the action handler.

Steps to reproduce

Here's an abridged version of my function, can provide more if wanted:

export default SlackFunction(RequestApprovalFunction, async ({ inputs, client, env }) => {
  console.log("Function invoked")
  const octokit = await getOctokit(env)

  const msgResponse = await client.chat.postMessage({
    channel: RELEASE_CHANNEL_NAME,
    blocks: [
      {
        type: "actions",
        block_id: "approve-deny-buttons",
        elements: [
          {
            type: "button",
            text: {
              type: "plain_text",
              text: "Approve",
            },
            action_id: APPROVE_ID,
            style: "primary",
          },
          {
            type: "button",
            text: {
              type: "plain_text",
              text: "Deny",
            },
            action_id: DENY_ID,
            style: "danger",
          },
        ],
      },
    ],
    text: `<@${inputs.requestingUser}> has requested approval to deploy '${inputs.releaseName}' to production.`,
  })

  if (!msgResponse.ok) {
    console.log("Error during request chat.postMessage!", msgResponse.error)
  }

  console.log("return completed: false")
  return {
    completed: false,
  }
}).addBlockActionsHandler(
  [APPROVE_ID, DENY_ID],
  async function ({ action, body, client  }) {
    console.log("Block action handler invoked")

    await client.functions.completeSuccess({
      function_execution_id: body.function_data.execution_id,
    })
  },
)

I do have esm.sh in my outgoingDomains. This is my first time working with the Deno ecoystem, so I'm not sure if there's something about the import being funky, etc.

Expected result

I'd expect the action handler to be called.

Actual result

See above.

Requirements

Please read the Contributing guidelines and Code of Conduct before creating this issue or pull request. By submitting, you are agreeing to those rules.

[hello-ashleyintech]

Hi, @oeed! Thanks for submitting your issue 😄

Consulted internally with the team and we wanted to see how long it's taking your Octocat function to run - there's a chance it could be hanging or taking too long and it may be timing out 😞

[oeed]

I added timestamp logs and it appears the entire function only takes a little over a second to execute. Just in case I didn't explain properly initially, it fails purely from constructing the Octokit class – you don't need to send a request for it to fail.

Another observation is that if you don't click an action button, i.e. just leave it, it also fails about 15 seconds later. So presumably it is actually timing out, even though I return from the function. Presumably Octokit is running something in the background, I'll try investigate what that might be.

2024-06-28 09:45:45 [info] [Wf079C8UQXRD] (Trace=Tr07A221QK5K) Shortcut trigger successfully started execution of function 'Request Release Approval'
2024-06-28 09:45:45 [info] [Fn079PU53U1K] (Trace=Tr07A221QK5K) Function 'Request Release Approval' (workflow function) started
2024-06-28 09:45:45 [info] [Wf079C8UQXRD] (Trace=Tr07A221QK5K) Workflow 'Request Release Approval' started
2024-06-28 09:45:45 [info] [Wf079C8UQXRD] (Trace=Tr07A221QK5K) Workflow step 1 of 1 started
2024-06-28 09:45:45 [info] [Fn079SU16U0J] (Trace=Tr07A221QK5K) Function 'Request Release Approval' (app function) started
Function invoked 2024-06-27T21:45:46.495Z
Getting GitHub token 2024-06-27T21:45:46.496Z
Got GitHub token
Got token 2024-06-27T21:45:47.158Z
Initialised Octokit 2024-06-27T21:45:47.161Z
return completed: false 2024-06-27T21:45:47.738Z
2024-06-28 09:46:01 [error] [Fn079SU16U0J] (Trace=Tr07A221QK5K) Function 'Request Release Approval' (app function) failed
        event_dispatch_failed
2024-06-28 09:46:01 [error] [Wf079C8UQXRD] (Trace=Tr07A221QK5K) Workflow step 'Request Release Approval' failed
2024-06-28 09:46:01 [error] [Wf079C8UQXRD] (Trace=Tr07A221QK5K) Workflow 'Request Release Approval' failed
        Function failed to execute
2024-06-28 09:46:02 [error] [Fn079PU53U1K] (Trace=Tr07A221QK5K) Function 'Request Release Approval' (workflow function) failed
        Function failed to execute

Edit: Here's a minimum repro that is failing, link it up to a workflow triggered by a shortcut. Interestingly I get delayed Workflow step 'Octokit Failure Function' failed logs from previous runs over a minute later.

import { DefineFunction, SlackFunction } from "deno-slack-sdk/mod.ts"
import { Octokit } from "https://esm.sh/octokit@4.0.2?dts"

export const OctokitFailureFunction = DefineFunction({
  callback_id: "octokit_failure_function",
  title: "Octokit Failure Function",
  description: "Octokit Failure Function.",
  source_file: "functions/ocotokit_failure.ts",
  input_parameters: {
    properties: {},
    required: [],
  },
  output_parameters: {
    properties: {},
    required: [],
  },
})

export default SlackFunction(OctokitFailureFunction, async () => {
  console.log("Started", new Date())
  new Octokit()
  console.log("Ended", new Date())
  return {
    outputs: {},
  }
})

Started 2024-06-27T22:17:57.060Z
Ended 2024-06-27T22:17:57.063Z
2024-06-28 10:17:55 [info] [Wf079C8UQXRD] (Trace=Tr07A25M3TN1) Shortcut trigger successfully started execution of function 'Request Release Approval'
2024-06-28 10:17:56 [info] [Fn079PU53U1K] (Trace=Tr07A25M3TN1) Function 'Request Release Approval' (workflow function) started
2024-06-28 10:17:56 [info] [Wf079C8UQXRD] (Trace=Tr07A25M3TN1) Workflow 'Request Release Approval' started
2024-06-28 10:17:56 [info] [Wf079C8UQXRD] (Trace=Tr07A25M3TN1) Workflow step 1 of 1 started
2024-06-28 10:17:56 [info] [Fn07A7G25CKE] (Trace=Tr07A25M3TN1) Function 'Octokit Failure Function' (app function) started
2024-06-28 10:17:57 [info] [Fn07A7G25CKE] (Trace=Tr07A25M3TN1) Function 'Octokit Failure Function' (app function) completed
2024-06-28 10:17:57 [info] [Wf079C8UQXRD] (Trace=Tr07A25M3TN1) Workflow step 'Octokit Failure Function' completed
2024-06-28 10:17:58 [info] [Fn079PU53U1K] (Trace=Tr07A25M3TN1) Function 'Request Release Approval' (workflow function) completed
2024-06-28 10:17:58 [info] [Wf079C8UQXRD] (Trace=Tr07A25M3TN1) Workflow 'Request Release Approval' completed
2024-06-28 10:18:11 [error] [Fn07A7G25CKE] (Trace=Tr07A25M3TN1) Function 'Octokit Failure Function' (app function) failed
        event_dispatch_failed
2024-06-28 10:18:12 [error] [Wf079C8UQXRD] (Trace=Tr07A25M3TN1) Workflow step 'Octokit Failure Function' failed
2024-06-28 10:18:28 [error] [Wf079C8UQXRD] (Trace=Tr07A25M3TN1) Workflow step 'Octokit Failure Function' failed

[filmaj]

Hey @oeed , sorry about the delay here, finally found some time to look into this.

It seems the deno process is blocked when running the simple sample function you provided, that builds and creates an Octokit object. While the actual function handler completes execution, something in the esm.sh-transpiled Octokit code is preventing the deno process from shutting down. My guess is there is some weird code in the transpiled Octokit that causes the event loop to be unable to empty out, preventing the process from gracefully shutting down.

Took me a little bit to figure this out, but here's a test you can run on the function that exhibits the behaviour; run this from your app root and update the import statement to match the path to your custom function:

deno eval 'import f from "./functions/sample_function.ts";console.log("imported OK, now will run...", await f({}));console.log("all done")'

When new Octokit() commented out, the above deno process completes and returns. If I leave it in, then the deno process blocks indefinitely.

[filmaj]

Looked into a workaround. I have good news and bad news.

Good news! If you use import { Octokit } from 'npm:octokit', the above test now passes.

Bad news 😬 npm: import support w/ slack deploy has a major issue, as you've recently discovered, it seems (https://github.com/slackapi/deno-slack-hooks/issues/89)

I will push on Slack's side to fix the npm issue.