Firebase-functions: Possible regression: Duplicate Firestore trigger event ids

[kimroen]

[REQUIRED] Version info

node:
v8.11.1

firebase-functions:
2.0.5

firebase-tools:
6.3.0

firebase-admin:
6.0.0

[REQUIRED] Test case

With the following onCreate triggers deployed for the same document:

const functions = require('firebase-functions');
const admin = require('firebase-admin');

exports.functionOne = functions.firestore
  .document('/users/{userId}')
  .onUpdate((snapshot, context) => {
    console.log(context.eventId);
  });

exports.functionTwo = functions.firestore
  .document('/users/{userId}')
  .onUpdate((snapshot, context) => {
    console.log(context.eventId);
  });

[REQUIRED] Steps to reproduce

With the above functions deployed, create a document in the users collection.

[REQUIRED] Expected behavior

The two functions should be called with unique event ids. These should be logged and be different.

[REQUIRED] Actual behavior

The two logged event ids are the same.

Description

I'm not sure if this report belongs in this repo, but using this was where the problem appeared and I wasn't able to see that the event id comes from elsewhere that I can access.

At some point recently, triggers on the same document like defined above started getting the same event id. Previously if there were multiple triggers for the same document, the event id would have an appended part (like long-uuid-0 and long-uuid-1).

This change caused the code we use to make the functions idempotent to no longer work, and only the first function that reacted to the change was allowed to run.

I haven't been able to find information about this change anywhere so far, so I'd be curious if there's anywhere I've missed.

Thanks!

[thechenky]

Hi @kimroen, thanks for posting this issue. To clarify, are you seeing the same eventid in the first part before the postfix (before the -0 and -1)? And when did this behavior change for you - do you recall how many days ago?

[kimroen]

To clarify, are you seeing the same eventid in the first part before the postfix (before the -0 and -1)?

This is correct.

And when did this behavior change for you - do you recall how many days ago?

We noticed a lot of strange behavior caused by this yesterday afternoon, but it could have been before then without us noticing.

[inlined]

Hi Kimroen, the event ID has been a slightly nebulous subject and we're trying to help add more meaning/standardization to something that was previously not crisply defined.

I completely understand why the event ID alone might be getting used as an idempotency key. I think I myself have recommended the shortcut. The Event ID describes the thing that happened, not the thing that happened + the thing handling it. This means that in the uncommon case where you will have two event handlers talking to the same services (and thus have a potential key collision) you'll want to add some extra info to your Event ID to make the idempotency key.

This is a bit of extra work for your use case, but seems like the right tradeoff. It's always possible to rehash something with new info (e.g. creating an idempotency key from event ID + Function) but you can't undo this operation on an opaque hash. For example, this design is the only way your functions could intentionally coordinate their work so that a 3rd function handles the results of the first two on a per-event basis.

[kimroen]

Thanks for the clarification - the reasoning totally makes sense. It's a much clearer model.

This means that in the uncommon case where you will have two event handlers talking to the same services (and thus have a potential key collision) you'll want to add some extra info to your Event ID to make the idempotency key.

Thanks for the tips! What we did to fix this here is to prepend the name of the function to the event id to create an idempotency key. We had to pass this in though, so I'd love it if you had any suggestions for more practical ways to solve this. Maybe there's something clever on the context we could use to identify the function uniquely?

---

What I'm curious about though, is is there anywhere we could have learned about this change in advance to avoid having the change affect our app running in production? I'm not saying there ought to have been marked a breaking change (it's an implementation detail), it's just that if there is a place we should pay attention to, I want to know.

[mbleigh]

process.env.FUNCTION_NAME should contain the name of the executing function.

[inlined]

What I'm curious about though, is is there anywhere we could have learned about this change in advance to avoid having the change affect our app running in production? I'm not saying there ought to have been marked a breaking change (it's an implementation detail), it's just that if there is a place we should pay attention to, I want to know.

This is certainly something I would rather not have caused customer pain over. In general at Google there's two types of changes:

1. Things that are so obviously innocuous that we don't tell anyone
2. Things that are so obviously disruptive that we tell/work with everyone

Because EventID's format was not documented, this seemed like a bugfix, and the fix matches both the recommendations of the CloudEvents working group and other implementations at Google like Cloud Storage, we assumed this change was in the first category.

[kimroen]

Thanks again for the explanation - much appreciated.

process.env.FUNCTION_NAME should contain the name of the executing function.

That's useful to know! Not quite sure how we would replicate that during testing, but maybe we'll figure something out 😄