Auth error 401 once per day for admin messaging

[trentbrooks]

Related issues

[REQUIRED] Version info

node: 8

firebase-functions: 7.0.0

firebase-admin: 2.2.0

[REQUIRED] Test case

I run a function every 15 minutes which sends out topic notifications via admin.messaging(), which works extremely well 95% of the time. But just once per day I get authentication error 401 (Unauthorized). It always occurs around the same time 730-930am UTC. I'm using the same global default admin initializeApp().

If there is a way to determine the admin auth status or if a cold start is required, then I might be able to re-intialise before the error?

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

const admin = require('firebase-admin');
admin.initializeApp();

exports.indicatorsUpdated_15m = functions.firestore.document('indicators/15m').onWrite((change, context) => {
    // topic notification code: eg. admin.messaging().sendToTopic()
});

[REQUIRED] Steps to reproduce

Described in test case

[REQUIRED] Expected behavior

No authentication error, and notifications get sent as normal same as other 95% of the day.

[REQUIRED] Actual behavior

Returns auth error, and notifications do not get sent for this one 15 minute window, and it results in a cold restart taking 15-30 seconds.

[inlined]

This issue seems to have slipped through the cracks; we're very sorry about that. Can you confirm whether the issue is still happening? It's possible that there's a bug in the token refresh code.

[trentbrooks]

Hi - thanks for response, yes this is still happening for our live app. I actually forgot about it myself- but just checked the cloud functions logs, and it still occurs once or twice per day- doesn't seem to be the same fixed UTC time anymore.

For context, I'm sending out 200-300 topic notifications every 15 minutes. The majority of these send fine, but at least once per day it fails with the same 401 auth error* and does not send. When the next 15 minute comes, it goes back to normal / auth + sends fine.

Would love some advice.

• 'An error occurred when trying to authenticate to the FCM servers. Make sure the credential used to authenticate this SDK has the proper permissions.'

[inlined]

Are you using any other Firebase APIs in this function, or just FCM? About how long does your function execute before it hits the 401 error? I'm wondering if there's a token that's not getting refreshed fast enough somewhere.

Also, how are you sending these notifications? Does your code look like:

for (let topic in topics) {
  await admin.messaging.sendToTopic(topic);
}

or

let promises = []
for (topic in topics) {
  topics.push(admin.messaging().sendToTopic(topic));
}
await Promise.all(promises);

My suspicion in the latter case would be that the SDK to gets a cached token for those 200-300 topics synchronously and then queues the HTTP requests. Eventually a request gets a chance to run but the token has expried. The workaround would be something like:

// something close to a reasonable connection pool size
const MAX_BATCH_SIZE = 10;
let batch = []
for (topic in topics) {
  topics.push(admin.messaging().sendToTopic(topic));
  if (batch.length === MAX_BATCH_SIZE) {
    await Promise.all(batch);
    batch = [];
  }
}
await Promise.all(batch);

This would still let you run ~10 requests in parallel at a time, but would keep the token freshness check happening around when the HTTP request actually gets processed by the networking stack.

[trentbrooks]

I am only using the admin.messaging.sendToTopic() call in the function. Takes about 5 seconds to run (on both the error calls, and successful). And I am using the latter example with promises.

I am going to try the batch example you posted- thanks for the tip. If it is an expired token, is there a way to increase the expiration timeout (eg. google cloud console)?

[inlined]

If it only takes 5s that reduces the chances that my suspicion is accurate. There's no way to increase the TTL of tokens, but that's not the right approach anyway. Any number you come up with (within reason) could be too short for a reasonable workload. From what I read in the credential section of the Admin SDK we're fetching the token every time for this type of Credential. IIRC the metadata service that provides you your credential can return credentials that expire within a few seconds. Its implementation is itself a cached credential that may expire within 1 day. That could explain your daily behavior, though the chances are slimmer if this is only a 5s request storm.

[trentbrooks]

I also run another identical function on the 1H (eg. send 200-300 topic notifications every hour), and there are no problems. Both functions work exactly the same, but only the 15 minute frequency seems to throw the 401 errors.

Originally I thought the 15m was catching the errors off a cold startup, leaving the other functions to run fine. But now the error frequency is more sporadic, I'm not sure what else it could be? Would gladly test any alternative suggestions you might have?

[inlined]

With your permission I'd like to look at some production metrics for your functions. Rather than posting personally identifiable information here, can you contact support with the name of your project, the function that runs every 15m & fails, and the function that runs every hour and succeeds? If you give me your case ID I can look into things further.

[trentbrooks]

Thank you @inlined. I have submitted a minimal code example with the project name to support. The case ID is: 00115392

[inlined]

I'm having trouble looking up the case on my side; there's lots of privacy protection measures at Google that are blocking me from searching for your case. Mind telling them to assign the bug to "inlined"?

[trentbrooks]

Done - thanks again @inlined

[trentbrooks]

Hey @inlined, not much activity on this yet so thought i'd ask if there was a temporary fix I could apply to circumvent this error? eg. can i check the admin auth status before sending messages and reconnect if required?

[inlined]

I'm bypassing some of the communication channels by responding both internally and externally, but I found out that your functions are crashing much more than once per day. Some are crashing more frequently than once per hour, and tokens have a 6hour expiry, so my suspicion is unlikely correct. I kicked the bug over to another org, but if my suspicion is wrong, this is going to be much harder to diagnose or fix.

Also, as an aside, I noticed some timeout errors. You'll want to make sure you're handling both success and error cases in your promises correctly. I don't know what the bug is since I never saw your code, but that's something to look into.

[trentbrooks]

Yes- I am only trying to solve the 401 auth error at the moment. As mentioned, this used to occur once per day on the 15 minute scheduled function, but now occurs multiple times per day. Same exact function triggers on the 1 hour, 4 hour, daily, weekly- with no problem. I've been scouring through docs, examples, and source code the last few weeks- but cannot find anything actionable in regards to the 401, and/or how to refresh the admin token.

What do you mean 'my suspicion is unlikely correct'? And where in the source/docs does it say tokens expire after 6 hours?

Getting desperate at this point- will try any suggestions. I have been running these functions on a live app for just over a year, but the consistency of alerts on the 15 minute- has now become a serious issue.