Slack Bolt for Python not acknowledging fast enough

GeekyAndDangerous commented 1 year ago

Hey all, long time listener, first time caller. I am working through developing a slack bot using slack bolt and AWS Lambda. I am attempting to implement slash commands and have used the 'lazy listener' method. My problem is that the acknowledgement isn't being sent back to Slack fast enough to avoid the 'operation timeout'. I have given the Lambda the invoke permissions.

Reproducible in:

app = App(
    process_before_response=True,
    token= os.getenv('BOT_TOKEN'),
    signing_secret=os.getenv('SIGNING_SECRET')
    )

command = "/test-prompt"

def respond_to_slack_within_3_seconds(body, ack):
    ack()

def process_request(say, body, command):
    # time.sleep(5)
    question = command['text']
    text = ai_response(question)

    person = app.client.users_info(
    user = command['user_id']
    )
    # respond(f'*{person["user"]["profile"]["real_name"]}* asks "*_{question}_*"')
    # say(command['text'])
    say(f'{text}______________________________________________________')

app.command(command)(ack=respond_to_slack_within_3_seconds, lazy=[process_request])

Python runtime version

3.9

Steps to reproduce:

(Share the commands to run, source code, and project settings (e.g., setup.py)) As above code. 1. 2. 3.

Expected result:

I would expect that the ack would be sent faster (when I remove the processing of the external http request found in the ai_response() method, the ack gets through quickly enough)

Actual result:

It seems to be processing all of the request still before sending the ack.

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.

filmaj commented 1 year ago

Hi @GeekyAndDangerous,

Have you taken a look at the AWS Lambda example? One thing that's unclear to me in your example is where is the Lambda entrypoint? Typically there is a handler exported/available in your Lambda function code (just like in the AWS Lambda example we have in the bolt-python repository).

I am able to deploy the above example to Lambda and have it respond without issue.

GeekyAndDangerous commented 1 year ago

@filmaj Thank you for your response. I realise I should have posted the whole code 🤦

I the middle, you can see where I have tried using the @app.command decorator, but that takes longer to acknowledge.

from slack_bolt import App
from slack_bolt.adapter.aws_lambda import SlackRequestHandler
import os
import json
import urllib
from urllib.request import Request, urlopen
import boto3
from botocore.exceptions import ClientError
import logging
import time

app = App(
    process_before_response=True,
    token= os.getenv('BOT_TOKEN'),
    signing_secret=os.getenv('SIGNING_SECRET')
    )

command = "/test-prompt"

def respond_to_slack_within_3_seconds(body, ack):
    ack()

def process_request(say, body, command):
    # time.sleep(5)
    question = command['text']
    text = ai_response(question)

    person = app.client.users_info(
    user = command['user_id']
    )
    # respond(f'*{person["user"]["profile"]["real_name"]}* asks "*_{question}_*"')
    # say(command['text'])
    say(f'{text}______________________________________________________')

app.command(command)(ack=respond_to_slack_within_3_seconds, lazy=[process_request])

# @app.command("/test-prompt")
# def ack_fast(body, ack, command, say):
#     ack(f"Acknowledging fast")

# # def lazy_merge_back(command, say):
#     question = command['text']
#     text = ai_response(question)

#     person = app.client.users_info(
#     user = command['user_id']
#     )
#     say(f'*{person["user"]["profile"]["real_name"]}* asks "*_{question}_*"')
#     # say(command['text'])
#     say(text)
#     say("______________________________________________________")

def ai_response(question):
    data = {"model": "text-davinci-003",
        "prompt": question,
        "temperature": 0,
        "max_tokens": 1000}
    url = "https://api.openai.com/v1/completions"
    token = os.getenv('OPENAI_KEY')

    req =  Request(url, data=json.dumps(data).encode('utf-8')) # this will make the method "POST"
    req.add_header('Authorization', f'Bearer {token}')
    req.add_header('Content-Type', 'application/json')
    resp = urlopen(req)
    resp_data = json.loads(resp.read().decode())
    slack_response = ""
    for x in resp_data['choices']:
        slack_response += x['text'].lstrip() + "\n"
    # openai.api_key = "now-rotated-api-key"
    # response = openai.Completion.create(model="text-davinci-003", prompt=question, temperature=1, max_tokens=100)
    # text = response.choices[0].text
    return slack_response

SlackRequestHandler.clear_all_log_handlers()
logging.basicConfig(format="%(asctime)s %(message)s", level=logging.DEBUG)

def lambda_handler(event, context):
    slack_handler = SlackRequestHandler(app=app)
    return slack_handler.handle(event, context)

kevinfaganworkday commented 1 year ago

I'm experiencing the exact same issue. Running both the standard and lazy sample apps, I receive the same response. i.e.

import logging

from slack_bolt import App
from slack_bolt.adapter.aws_lambda import SlackRequestHandler

# process_before_response must be True when running on FaaS
app = App(
    token="xoxb-....",
    signing_secret="....",
    process_before_response=True,
)

@app.event("app_mention")
def handle_app_mentions(body, say, logger):
    logger.info(body)
    say("What's up?")

@app.command("/foo")
def respond_to_slack_within_3_seconds(ack):
    ack()

SlackRequestHandler.clear_all_log_handlers()
logging.basicConfig(format="%(asctime)s %(message)s", level=logging.DEBUG)

def lambda_handler(event, context):
    slack_handler = SlackRequestHandler(app=app)
    return slack_handler.handle(event, context)

In slack:

/foo failed with the error "operation_timeout"

One thing I had noticed from the lambda logs is that the command function returns a 200 so the ack() seems to be working however it has its content type is set to text/plain;charset=utf-8 which doesn't seem right?

filmaj commented 1 year ago

One thing I notice in both of your code is that the entry point / handler into your code is called lambda_handler - this is different from the example provided in the repo (the example uses handler, which is an AWS Lambda default for all languages). If you are using the config.yaml in the example to set up your Lambda, then make sure this function name matches the handler property in the config file; see here in the example.

You can also double check this configuration directly on AWS Console by opening up the AWS Lambda instance in your Console, flipping to the Code tab, scroll down to Runtime settings and see what value you have under Handler. Here is a screenshot of that on my own personal AWS account for a working bolt-python Lambda function:

Please take a look at the AWS Lambda documentation on what this value refers to in the context of a Python function. The term before the . is the file name, and the term after the . is the function or method name.

kevinfaganworkday commented 1 year ago

Thanks @filmaj, I appreciate you taking a look. I made sure to check this and the entry point maps correctly to my cloud formation template

Resources:
  SlashCommandFunction:
    Type: AWS::Serverless::Function # More info about Function Resource: https://github.com/awslabs/serverless-application-model/blob/master/versions/2016-10-31.md#awsserverlessfunction
    Properties:
      CodeUri: slash_command/
      Handler: app.lambda_handler
      Runtime: python3.9
      Architectures:
        - x86_64
      Events:
        SlashCommand:
          Type: Api # More info about API Event Source: https://github.com/awslabs/serverless-application-model/blob/master/versions/2016-10-31.md#api
          Properties:
            Path: /slash_command
            Method: post

I'm almost 100% this isn't the issue. I can see the request being routed to my entry point and the ack() command does result in a response to slack however it seems slack doesn't like what it receives.

This is the response from my lambda function which shows it exiting correctly and returning a 200 response:

Mounting /Users/kevin/Development/python/repo_config/.aws-sam/build/SlashCommandFunction as /var/task:ro,delegated inside runtime container
START RequestId: 0fc183ad-e8c6-4ffc-b8ed-59b086ab2458 Version: $LATEST
lambda_handler
respond_to_slack_within_3_seconds
END RequestId: 0fc183ad-e8c6-4ffc-b8ed-59b086ab2458
REPORT RequestId: 0fc183ad-e8c6-4ffc-b8ed-59b086ab2458  Init Duration: 0.99 ms  Duration: 2787.85 ms    Billed Duration: 2788 ms    Memory Size: 128 MB Max Memory Used: 128 MB 
2022-12-14 13:47:56 127.0.0.1 - - [14/Dec/2022 13:47:56] "POST /slash_command HTTP/1.1" 200 -

And this is what ends up going over the wire to slack

==================== REQUEST ====================
Received at: 2022-12-14T13:47:53Z
Request ID: 31470e77-28df-4447-9b25-99fd64a694d9
URI: /slash_command
Method: POST
Headers: 
  - [X-Forwarded-Port] = 443
  - [X-Forwarded-Proto] = https
  - [X-Slack-Request-Timestamp] = 1671025673
  - [Accept] = application/json,*/*
  - [Accept-Encoding] = gzip,deflate
  - [Content-Length] = 491
  - [Via] = 1.1 b467a4a34e9f37bba6d2f0aba8257b5e.cloudfront.net (CloudFront)
  - [Content-Type] = application/x-www-form-urlencoded
  - [User-Agent] = Slackbot 1.0 (+https://api.slack.com/robots)
Body: 
token=....(omitted for security)
==================== RESPONSE ====================
Responded at: 2022-12-14T13:47:56Z
Request ID: 31470e77-28df-4447-9b25-99fd64a694d9
Status: 200
Headers: 
  - [Server] = Werkzeug/2.0.3 Python/3.8.16
  - [Date] = Wed, 14 Dec 2022 13:47:56 GMT
  - [Content-Type] = text/plain;charset=utf-8
  - [Content-Length] = 0
Body: [EMPTY]

filmaj commented 1 year ago

While the specific content of the response does matter to respond in different ways, at the most basic of levels, any HTTP 200 response is considered acceptable for Slack (see our docs on the subject here).

@kevinfaganworkday are the following logs you posted from the relevant handlers?

lambda_handler
respond_to_slack_within_3_seconds

I.e. the first one is something being logged out from the lambda_handler method, the second one from the respond_to_slack method, etc.? Or is that coming from the debug logging configuration?

Another thing I noticed: the timing is awfully close / right at the 3 second timeout:

==================== REQUEST ====================
Received at: 2022-12-14T13:47:53Z
...
==================== RESPONSE ====================
Responded at: 2022-12-14T13:47:56Z

Exactly three seconds. Add to that any transit time from AWS to Slack, maybe we are legitimately hitting the timeout?

Last thing I noticed: the Lambda seems to be hitting its memory limit. Looks like your Lambda has 128MB assigned to it, and based on the AWS Lambda logs, all 128MB are being consumed:

Duration: 2787.85 ms    Billed Duration: 2788 ms    Memory Size: 128 MB Max Memory Used: 128 MB

Are you able to bump up the memory allocation at all? I wonder if some kind of memory thrashing as the RAM is completely used up is happening, slowing down the response?

Here is me running the AWS Lazy Lambda example on my account, and the relevant details, and the example works as expected:

Duration:
297.93 ms Billed Duration: 298 ms Memory Size: 512 MB Max Memory Used:
70 MB Init Duration: 539.78 ms

kevinfaganworkday commented 1 year ago

Thanks @filmaj. So after debugging some more on this end I'm pretty sure this is an issue on my side. Originally I was testing locally with ngrok setup to route the slack response to my localhost. I've since deployed the changes to aws and tested there and it's working without issue.

I'm not entirely sure why a local setup wouldn't work but I suspect there's some networking issues at play somewhere through the stack.

Apologies for the red herring and I really appreciate you taking some time out to help me debug.

slackapi / bolt-python