Firebase firestore update running 3 minutes after rest of the function completes

Question

I have a GCP Firebase function set up like this:

exports.sendEmail = functions.firestore.document('/work_orders/{documentId}')
  .onUpdate(async (change, context) => {

   // code here --
   // then ends like this:

    functions.logger.log('Log Before Interval Start')
    const interval = setInterval(async ()=> {
        if (attachment && attachment_2){ 
            clearInterval(interval)
            functions.logger.log('Attachments Ready')

            const resp = await send_email()
            functions.logger.log('Doc Created', context.params.documentId, newValue)
            functions.logger.log('Resp Created', resp)
            return change.after.ref.update({emailSent: true, createEstimateEmail: false})
    }, 1000)
    functions.logger.log('Log After Interval')
})

Everything runs fine. The email sends immediately. But when it comes to change.after.ref.update part, that takes around 3 minutes to make that simple commit. And when it finally completes, it triggers the function to run again, since it is onUpdate. (The second run exits as soon as it checks the flag as to whether it should run)

Is there a way I can have this commit right away?

Updated: Logs. You can see that 4 minutes later the function is retriggered. This trigger must be due to the updated firestore doc. And you can see it ends immediately, because the function checks createEstimateEmail and ends if it is false. So, it takes around 4 minutes for that last line to run. (And if I check Firestore using Google Console, it also doesn't update for a few minutes after it finishes running.)

2022-01-02 10:30:41.968 ASTsendEmail51lrasb9sh8s Function execution started
2022-01-02 10:30:44.058 ASTsendEmail51lrasb9sh8s Log Before Interval Start
2022-01-02 10:30:44.059 ASTsendEmail51lrasb9sh8s Log After Interval
2022-01-02 10:30:44.124 ASTsendEmail51lrasb9sh8s Function execution took 2158 ms, finished with status: 'ok'
2022-01-02 10:30:45.060 ASTsendEmail51lrasb9sh8s Attachments Ready
2022-01-02 10:30:45.060 ASTsendEmail51lrasb9sh8s Attachments Ready
2022-01-02 10:30:51.336 ASTsendEmail51lrasb9sh8s Doc Created vKFOnZ9usRaDiJ6Nu9Yk
2022-01-02 10:30:51.937 ASTsendEmail51lrasb9sh8s Resp Created [ Response { statusCode: 202, body:....

2022-01-02 10:34:20.391 ASTsendEmail51lrfqr7kldb Function execution started
2022-01-02 10:34:20.402 ASTsendEmail51lrfqr7kldb Function execution took 12 ms, finished with status: 'ok'

Can you also provide the logs? Also include statements and their output in the post, so we can see precisely where the time is going. — RJC, Dec 31 '21 at 08:52

score 1 · Accepted Answer · answered Jan 02 '22 at 15:18

Fixed it after adding more logging points/logs as suggested by RJC. Essentially, the function was ending before all the work was done.

This answer helped, dealing with setInterval(): https://stackoverflow.com/a/56469184/7089055

Final code that works correctly inside the main onUpdate() function:

    async function waitUntil() {
      return await new Promise(resolve => {
        const interval = setInterval(() => {
          if (attachment && attachment_2) {
            clearInterval(interval);
            const msg = {....};
            resolve(msg);
          };
        }, 1000);
      });
    }

    const msg = await waitUntil()
    const resp = await sgMail.send(msg)
    return change.after.ref.update({emailSent: true, createEstimateEmail: false})

Firebase firestore update running 3 minutes after rest of the function completes

1 Answers1