Bot webhook not waiting for session middleware to finish

[elC0mpa]

I am migrating a long polling bot to webhook using AWS Lambda. I added '@telegraf/session/mongodb' package to store sesion info in my mongodb database.
After I finished setting up my bot everything works fine but the wizard scenes. I started debuguing and it looks like the problem is related to the session middleware. Let me show you my AWS Cloudwatch logs:

2023-12-20T14:25:29.214Z telegraf:session (642696426) did not find cached session
2023-12-20T14:25:29.214Z telegraf:session (642696426) fetching from upstream store
END RequestId: 5b8e1b5d-4e74-4691-83ac-d21894357d13

As you can see it doesn't print the following message:

2023-12-20T14:25:39.277Z telegraf:session (642696426) updating cache

That's why my code never gets into the wizard scenes. Let me show you my code because maybe I am missing something

export const message = async (event: APIGatewayProxyEvent): Promise<APIGatewayProxyResult> => {
  try {
    const body = JSON.parse(event.body!)
    console.log(body)
    initBot()
    await webhookHandle(body)

    return { body: JSON.stringify({ message: 'Ok' }), statusCode: 200 }
  } catch (error) {
    return { body: JSON.stringify({ message: 'Error' }), statusCode: 500 }
  }
}

webhookHandle function:

const webhookHandle = (update: Update) => {
  return bot.handleUpdate(update)
}

My problem basically is that I don´t know why but the webhook handle function is not waiting for the bot to completely handle the update

I added this to my code and everything works perfectly now:

    console.log('Finished webhook handle')
    await sleep(150)

I added this above the return statement inside the handler function and everything worked now. But it is not an elegant solution and I added 150 ms of billing time to every request, so the question is:

Why do you think it is not waiting for the bot to handle the update?

Let me show you my initBot function

const initBot = () => {
  const config = { telegram: { webhookReply: false } }
  bot = new Telegraf<BotContext>(process.env.BOT_TOKEN, config)
  const wizardsStage = new Scenes.Stage<any>([])
  const store = Mongo({
    url: process.env.DATABASE_URL,
    database: process.env.SESSION_DATABASE_NAME,
  })

  bot.use(checkUserType)
  bot.use(allowedUsers)

  bot.start(ctx => {
    console.log('start bot')
    return ctx.reply('Menú Principal', ctx.customState.isSalesman ? SalesmanMainmenuKeyboard : MainmenuKeyboard)
  })
  bot.hears(UserInteractionConstants.MAIN_MENU, ctx => {
    return ctx.reply('Menú Principal', ctx.customState.isSalesman ? SalesmanMainmenuKeyboard : MainmenuKeyboard)
  })
  initBrandsRoutes(bot, wizardsStage)
  initModulesRoutes(bot, wizardsStage)
  initInventoriesRoutes(bot, wizardsStage)
  initProductsRoutes(bot, wizardsStage)
  initCurrenciesRoutes(bot, wizardsStage)
  initSalesRoutes(bot, wizardsStage)
  initUsersRoutes(bot, wizardsStage)
  initPaymentsRoutes(bot, wizardsStage)
  initDoubtsRoutes(bot, wizardsStage)
  initSettingsRoutes(bot, wizardsStage)

  bot.use(session({ store }))
  bot.use(wizardsStage.middleware())
}

Now inside initCurrenciesRoute function (this is just an example of how it is implemented all routes for each entity)

export const initCurrenciesRoutes = (bot: Telegraf<BotContext>, wizardsStage: WizardsStageType) => {
  registerScenes(wizardsStage)
  bot.hears(UserInteractionConstants.CURRENCIES_MENU, ctx => {
    ctx.reply('Menú divisas', ctx.customState.isAdmin ? CurrencyActionsKeyboard : SalesmanCurrencyActionsKeyboard)
  })
  bot.hears(UserInteractionConstants.CURRENCY_INCREASE_ACTION, ctx => {
    ctx.reply('Incrementar divisas', CurrencyIncreaseKeyboard)
  })
  bot.hears(UserInteractionConstants.CURRENCY_DECREASE_ACTION, ctx => {
    ctx.reply('Decrementar divisas', CurrencyDecreaseKeyboard)
  })
  bot.hears(UserInteractionConstants.CURRENCY_EXCHANGE_ACTION, ctx => {
    ctx.reply('Intercambiar divisas', CurrencyExchangeKeyboard)
  })
  wizardsStage.hears(UserInteractionConstants.CURRENCY_QUERY_ACTION, async ctx => {
    console.log(`Inside ${UserInteractionConstants.CURRENCY_QUERY_ACTION}`);
    const customState: BotState = (ctx as any).customState
    if (customState.isAdmin) {
      ctx.reply('Consultar divisas', CurrencyQueryKeyboard)
    } else if (customState.isSalesman) {
      ctx.scene.enter(SceneIDS.QUERY_CURRENCIES_SALESMAN)
    }
  })
  bot.command('query_currencies', ctx => {
    const customState: BotState = (ctx as any).customState
    if (customState.isAdmin) {
      ctx.reply('Consultar divisas', CurrencyQueryKeyboard)
    } else if (customState.isSalesman) {
      ctx.scene.enter(SceneIDS.QUERY_CURRENCIES_SALESMAN)
    }
  })
}

[MKRhere]

You should await your ctx.scene.enter calls. When you don't await them, the async chain is lost, and Lambda is free to consider the request handled, even though things are happening in the background.

Another observation is that you should move initBot outside the request handler as an optimisation; you'd want it to happen when the Lambda warms up instead of on every request. initBot doesn't even need to be a function call. Its contents can just live outside. Is there any reason you chose to do it this way?

It's still a little bit weird that it kills the Lambda before updating store is logged; I would have expected it to some times update store before scene.enter is able to write back. Anyway, try these suggestions and let us know if this helped at all.

[elC0mpa]

I just made the changes you suggested. First of all thank you for letting me now about the initBot function. I already fixed that and I also added await to the ctx.scene.enter calls. Now I realized about something I will show you:

  wizardsStage.hears(UserInteractionConstants.CURRENCY_QUERY_ACTION, async ctx => {
    console.log(`Inside ${UserInteractionConstants.CURRENCY_QUERY_ACTION}`);
    const customState: BotState = (ctx as any).customState
    if (customState.isAdmin) {
      ctx.reply('Consultar divisas', CurrencyQueryKeyboard)
    } else if (customState.isSalesman) {
      await ctx.scene.enter(SceneIDS.QUERY_CURRENCIES_SALESMAN)
    }
  })

As you can see I have a log inside this function just to know when this logic is executed

I also have a log when the webhook handle function finished

export const message = async (event: APIGatewayProxyEvent): Promise<APIGatewayProxyResult> => {
  try {
    const body = JSON.parse(event.body!)
    console.log(body)
    await webhookHandle(body)
    console.log('Finished webhook handle')
    return { body: JSON.stringify({ message: 'Ok' }), statusCode: 200 }
  } catch (error) {
    return { body: JSON.stringify({ message: 'Error' }), statusCode: 500 }
  }
}

However take a look at the AWS Cloudwatch logs when I execute this action

2023-12-28T09:14:59.604-05:00	START RequestId: cbfef857-daab-43e0-a871-1410d59d08a7 Version: $LATEST

2023-12-28T09:14:59.605-05:00	2023-12-28T14:14:59.605Z cbfef857-daab-43e0-a871-1410d59d08a7 INFO { update_id: 642697117, message: { message_id: 51836, from: { id: 551286447, is_bot: false, first_name: 'Jose Gabriel', last_name: 'Companioni Benitez', username: 'elC0mpa', language_code: 'en' }, chat: { id: 551286447, first_name: 'Jose Gabriel', last_name: 'Companioni Benitez', username: 'elC0mpa', type: 'private' }, date: 1703772898, text: 'Consultar Divisas 🔎' } }

2023-12-28T09:14:59.944-05:00	2023-12-28T14:14:59.944Z cbfef857-daab-43e0-a871-1410d59d08a7 INFO Finished webhook handle

2023-12-28T09:14:59.958-05:00	2023-12-28T14:14:59.958Z telegraf:session (642697117) did not find cached session

2023-12-28T09:14:59.958-05:00	2023-12-28T14:14:59.958Z telegraf:session (642697117) fetching from upstream store

2023-12-28T09:14:59.959-05:00	END RequestId: cbfef857-daab-43e0-a871-1410d59d08a7

I don´t know why, but it is like if webhookHandle function is not awaiting for anything. It returns even before that session middleware its doing its job

[elC0mpa]

I am thinking about solving this with the sleep workaround but I want to do it only when it is necessary. Is there any way for me to know when the session middleware is executed to add the 150 ms only in that situation?
I tried by registering a middleware after session but it didn't work because the session middleware doesn't finish unless I add the delay.

Any idea?

[MKRhere]

webhookHandle function is not awaiting for anything

Yeah, this is the root problem. It's still a missing await somewhere, but we're not able to nail where it is. Do you call next() anywhere without await or return, especially asynchronously? Maybe it's a rogue middleware library?

Worst case, are you open to privately sharing the codebase, if you want me to take a look at other potential issues?

[elC0mpa]

Yes, I have no problem on sharing the codebase with you, just let me know how could I proceed. Thanks in advance

[MKRhere]

Please reach out on Telegram, https://t.me/MKRhere

[elC0mpa]

Any update about this?