Cloud Function Sometimes Writes to FireStore AFTER another cloud function is triggered

Question

I'm currently having trouble with some cloud functions that only writes after another instance is triggered.

My cloud function code is below and is triggered from a pubsub event.

if (jsonData.Event == "TEST") {
  var msg = jsonData.Value;
  var timeOfReception = new Date();
  //changer l'occupation courante
  docRef
    .get()
    .then(function (doc) {
      if (doc.exists) {
        
       
        
        docRef.update({
          LastGesture: msg,

        }).then(function() {
        console.log("Write completed")
      }).catch(function(error) {
        console.error("Write failed: "+error)
      });       
     
      } else {
        // doc.data() will be undefined in this case
        console.log("No such document!");
      }
    })
    .catch(function (error) {
      console.log("Error getting document:", error);
    });
  }

Here is the log from the same cloud function :


2021-07-02 15:44:17.869 EDTpubsubToFireStoregsn141ejhe1b Function execution started
Default
2021-07-02 15:44:17.874 EDTpubsubToFireStoregsn141ejhe1b {Date: 2000/00/00-00:00:00, DeviceID: TSA00001, Event: TEST, Location: MAISON, Value: PRESENT, Version: 1.0, tableName: GestureTest}
Debug
2021-07-02 15:44:17.875 EDTpubsubToFireStoregsn141ejhe1b Function execution took 7 ms, finished with status: 'ok'
Default
2021-07-02 15:44:18.532 EDTpubsubToFireStoregsn141ejhe1b Write completed
Debug
2021-07-02 16:04:27.466 EDTpubsubToFireStore2o6osfooylkj Function execution started
Default
2021-07-02 16:04:27.513 EDTpubsubToFireStore2o6osfooylkj {Date: 2000/00/00-00:00:00, DeviceID: TSA00001, Event: TEST, Location: MAISON, Value: ABSENT, Version: 1.0, tableName: GestureTest}
Debug
2021-07-02 16:04:27.548 EDTpubsubToFireStore2o6osfooylkj Function execution took 85 ms, finished with status: 'ok'
Debug
2021-07-02 16:05:40.824 EDTpubsubToFireStore2o6ozvzxeri1 Function execution started
Default
2021-07-02 16:05:41.347 EDTpubsubToFireStore2o6ozvzxeri1 {Date: 2000/00/00-00:00:00, DeviceID: TSA00001, Event: TEST, Location: MAISON, Value: PRESENT, Version: 1.0, tableName: GestureTest}
Debug
2021-07-02 16:05:41.351 EDTpubsubToFireStore2o6ozvzxeri1 Function execution took 528 ms, finished with status: 'ok'
Default
2021-07-02 16:06:07.130 EDTpubsubToFireStore2o6ozvzxeri1 Write completed
Default
2021-07-02 16:06:07.830 EDTpubsubToFireStore2o6ozvzxeri1 Write completed

As you can see, the function at 15:44:17 works perfectly: The function is triggered and the write operation is performed. However, the function at 16:04:27 doesn't write until the function at 16:05:41 is triggered which as it shows, does the two writes almost at the same time.

I'm not really sure how to explain this behaviour as I'm still new to cloud functions. If there is anything that could point me to the right direction I would be really grateful :). I can provide further details if needs be. Thank you!

maganap maganap · Accepted Answer · 2021-07-04T14:35:47

The problem is that you're not waiting for your process to complete before the function receives an (undefined) return value, so the function is finishing before your code actually finishes to execute.

You must await to make sure your code is done before returning. In this case, your whole function is returning after the docRef.get(). The code inside the .then() got executed just by chance, but not because you waited for it.

When the function finishes, the instance gets in a "suspended" state. This same instance "wakes up" the next time you invoque your function. It is then when the "pending" executions from the previous invocation will finish running, since you didn't give them enough time to finish when it was its turn.

You can notice this by the timestamps and the invocation id: EDTpubsubToFireStore2o6ozvzxeri1 that prints the last 2 "Write completed". Also, the text "Function execution took [...]" should be the last thing printed, all the things you print should appear before this line.

You need to adjust your code to wait for the whole execution before returning. Something like:

exports.onWriteCol1 = functions.firestore.document('col1/{id}')
  .onWrite(async (change, context) => {
    /// whatever defines jsonData and docRef...
    if (jsonData.Event !== "TEST") {
      console.log('Nothing to do... leaving...');
      return;
    }
    const msg = jsonData.Value;
    //changer l'occupation courante
    try {
      const snap = await docRef.get();
      if ( snap.exists ) {
        await docRef.update({ LastGesture: msg });
        console.log("Write completed")
      }
    } catch (err) {
      console.error("Write failed: "+err);
    }
  });

Or just:

//changer l'occupation courante
await docRef.get().then(... return docRef.update() ... ).catch(...);

you need to return the update() in order to await for it above.

(I'm not such a fan of .then().catch() approach xD a matter of taste, I guess)

More details on terminating functions properly: here.

======

BTW, the console.error("Write failed: "+err); won't print as an error in the Firebase Functions logs because it's a string. It needs to be an actual new Error(). Or just use console.error(err) since err is already an instance of Error.

Cloud Function Sometimes Writes to FireStore AFTER another cloud function is triggered

1 Answers