1

I have a Cloud Firestore trigger that takes care of adjusting the balance of a user's wallet in my app.

exports.onCreateTransaction = functions.firestore
    .document('accounts/{accountId}/transactions/{transactionId}')
    .onCreate(async (snap, context) => {
        const { accountId, transactionId  } = context.params;

        const transaction = snap.data();

        // See the implementation of alreadyTriggered in the next code block
        const alreadyTriggered = await firestoreHelpers.triggers.alreadyTriggered(context);

        if (alreadyTriggered) {
            return null;
        }

        if (transaction.status === 'confirmed') {
            const accountRef = firestore
                .collection('accounts')
                .doc(accountId);

            const account = (await accountRef.get()).data();
            const balance = transaction.type === 'deposit' ? 
                    account.balance + transaction.amount : 
                    account.balance - transaction.amount;

            await accountRef.update({ balance });
        }

        return snap.ref.update({ id: transactionId });
    });

As a trigger may actually be called more than once, I added this alreadyTriggered helper function:

const alreadyTriggered = (event) => {
    return firestore.runTransaction(async transaction => {
        const { eventId } = event;
        const metaEventRef = firestore.doc(`metaEvents/${eventId}`);
        const metaEvent = await transaction.get(metaEventRef);

        if (metaEvent.exists) {
            console.error(`Already triggered function for event: ${eventId}`);
            return true;
        } else {
            await transaction.set(metaEventRef, event);
            return false;
        }
    })
};

Most of the time everything works as expected. However, today I got a timeout error which caused data inconsistency in the database.

Function execution took 60005 ms, finished with status: 'timeout'

What was the reason behind this timeout? And how do I make sure that it never happens again, so that my transaction amounts are successfully reflected in the account balance?

Frank van Puffelen
  • 565,676
  • 79
  • 828
  • 807
Yulian
  • 6,262
  • 10
  • 65
  • 92

1 Answers1

0

That statement about more-than-once execution was a beta limitation, as stated. Cloud Functions is out of beta now. The current guarantee is at-least-once execution by default. you only get multiple possible events if you enable retries in the Cloud console. This is something you should do if you want to make sure your events are processed reliably.

The reason for the timeout may never be certain. There could be any number of reasons. Perhaps there was a hiccup in the network, or a brief amount of downtime somewhere in the system. Retries are supposed to help you recover from these temporary situations by delivering the event potentially many times, so your function can succeed.

Doug Stevenson
  • 297,357
  • 32
  • 422
  • 441
  • Thanks for your answer! Triggers seem to get invoked more than once even if there's already been a successful invocation. Moreover, sometimes a second call is being made before the first one has returned. – Yulian Dec 11 '18 at 20:27
  • I am especially referring to the case when the trigger is being invoked with the same event id. Question is: will the event id be different from the first one if 'retry on failure' is enabled? – Yulian Dec 11 '18 at 20:33
  • I think you're going to have to be more specific about how exactly you're observing this behavior. – Doug Stevenson Dec 11 '18 at 20:49
  • 1
    Okay, I will try. In the following screenshot you can see that this trigger is being called more than once with the same event id: https://imgur.com/a/D1ubYQy – Yulian Dec 12 '18 at 09:21
  • 1
    The more important one though is that one: https://imgur.com/a/mgtXWx1 As you can see from the screenshot, c1 is the first call to the trigger that runs successfully. However, there are 2 more calls to the trigger, marked with c2 and c3, that are invoked just after it. Moreover, c3 seems to have started before c2 has finished. And in order to show you that c2 and c3 are really triggered for the same event as c1, I have underlined the parameters from c1 (d1 and d2) and its event id - d3. You can see that the id of the event being called in c2 and c3 matches with the parameters in the document. – Yulian Dec 12 '18 at 09:25
  • Your question talks about timeouts, but I don't see a timeout here. I also don't have visibility into what exactly is triggering your function. It's too hard to debug remotely. If you think there's a bug in the system, please file a bug report with the exact steps to reliably reproduce the problem. http://firebase.google.com/support/contact/bugs-features – Doug Stevenson Dec 12 '18 at 16:22
  • Yes, my question was about timeouts. However, in your answer you stated the following: "you only get multiple possible events if you enable retries in the Cloud console" and more specifically this one - "you only get multiple possible events if". That's why I asked you follow-up questions as why I get my trigger executed more than once even if the trigger has executed successfully and retries are NOT enabled. Then you asked me to be more specific about this behavior and I sent you the screenshots. – Yulian Dec 12 '18 at 16:37
  • Here's the timeout, along with another set of trigger invocations that are being called before the previous once had failed or returned at all: https://imgur.com/6MHGgNH – Yulian Dec 12 '18 at 16:43
  • The function is a Firestore onCreate trigger and I think the question is not about reproducing the problem but discussing if the behavior of triggers being called more than once unnecessarily and without any order is expected or not. – Yulian Dec 12 '18 at 16:45
  • Would you like to ask a new question that more concisely addresses the issue, if it's not about timeouts? – Doug Stevenson Dec 12 '18 at 21:23