httpsCallable keeps open a timer even after responses are received

[minism]

[REQUIRED] Describe your environment

• Operating System version: Ubuntu (on WSL, windows 10)
• Browser version: Using node v10.19.0
• Firebase SDK version: 7.0.0
• Firebase Product: functions

[REQUIRED] Describe the problem

httpsCallable keeps open a timer even after responses are received, due to this line here:

firebase-js-sdk/packages/functions/src/api/service.ts

Line 218 in ae31905

failAfter(timeout),

This causes undesirable behavior when utilizing the SDK in short run process, for example in integration tests. An immediate response from the cloud API will still cause the node process to stay alive for timeout milliseconds, due to this timer.

Instead, the SDK should be smart enough to cancel the unnecessary timer as soon as a response is received.

Steps to reproduce:

Example jest unit test:

firebase.initializeApp({})

test('function test', async () => {
  await firebase.auth().signInAnonymously()
  const fn = firebase.functions().httpsCallable('myFunction')
  await fn({})
})

Expectation: Test should finish in under 10 seconds.
Actual: Test waits for 70 seconds before terminating.

The open timer can be seen using the wtfnode package:

console.log node_modules/wtfnode/index.js:53
- Timers:

console.log node_modules/wtfnode/index.js:53
- (70000 ~ 1 min) (anonymous) @ ./node_modules/firebase/node_modules/@firebase/functions/dist/index.node.cjs.js:373

https://stackblitz.com/fork/firebase-issue-sandbox

// TODO(you): code here to reproduce the problem

[google-oss-bot]

I couldn't figure out how to label this issue, so I've labeled it for a human to triage. Hang tight.

[hsubox76]

Are you sure that fn is successful? I did try to replicate this using this setup:

import firebase from 'firebase/app';
import 'firebase/functions';

let start;

firebase.initializeApp({
  // ...
});

async function callFunctions() {
  console.log('CALLING FUNCTION');
  const callTest = firebase.functions().httpsCallable('callTest');
  const result = await callTest({data: 'abcd'});
  console.log('FUNCTIONS result:', result.data);
  console.log('MS ELAPSED:', Date.now() - start);
}

async function main() {
  start = Date.now();
  console.log('MAIN START');
  await callFunctions();
  console.log('MAIN END. MS ELAPSED:', Date.now() - start);
}

main();

Results:

MAIN START
app2.js:18 CALLING FUNCTION
app2.js:21 FUNCTIONS result: {word: "hellooo"}
app2.js:22 MS ELAPSED: 242
app2.js:29 MAIN END. MS ELAPSED: 243

The failAfter() function is part of a Promise.race() which will "cancel" (technically ignore) any other promises once any promise in the array resolves or rejects. If the http call to functions was successful, code execution will no longer wait for the other 2 promises in the array. It's possible there could be a bug, perhaps with a browser or environment that doesn't handle Promise.race() in an expected way, but I'm not seeing it so far in my simple repro.

If fn() in the test is not resolving, this will cause it to hang until the timeout resolves, so that seems like the simplest possibility. If that's not the case, and you do see a network response from the functions request, please let me know.

[google-oss-bot]

Hey @minism. We need more information to resolve this issue but there hasn't been an update in 5 weekdays. I'm marking the issue as stale and if there are no new updates in the next 5 days I will close it automatically.

If you have more information that will help us get to the bottom of this, just add a comment!

[minism]

Thanks for the response @hsubox76 , sorry for the delay!

Are you sure that fn is successful?

In fact, the bug is present even if the function you're trying to call does not exist.

The failAfter() function is part of a Promise.race() which will "cancel" (technically ignore) any other promises once any promise in the array resolves or rejects. If the http call to functions was successful, code execution will no longer wait for the other 2 promises in the array. It's possible there could be a bug, perhaps with a browser or environment that doesn't handle Promise.race() in an expected way, but I'm not seeing it so far in my simple repro.

The issue is not with Promise.race, that is working as expected. The httpsCallable function call immediately returns, that specific call doesn't hang.

The issue is that failAfter(timeout) creates a timer, and this timer hangs around which, in the case of node, prevents the process from cleanly exiting. I believe you would only observe this issue when running the code in node, which is what I'm doing (specifically in a jest unit test).

My suggestion is that the library code should delete the timer using clearTimeout when it knows it will no longer wait for the callback -- the timer serves no purpose at that point.

If fn() in the test is not resolving, this will cause it to hang until the timeout resolves, so that seems like the simplest possibility. If that's not the case, and you do see a network response from the functions request, please let me know.

I probably didn't describe it well initially -- fn() resolves just fine. The problem is the lingering timer created by it.

[hsubox76]

That makes sense, but I'm having no luck trying to reproduce it. I created a simple project that only runs a Jest test, like this:

const firebase = require('firebase');

firebase.initializeApp({
  //...
});

test('function test', async () => {
  await firebase.auth().signInAnonymously();
  const callTest = firebase.functions().httpsCallable('callTest');
  const result = await callTest({data: 'abcd'})
  console.log('FUNCTIONS result:', result.data);
});

Then I run Jest from the command line:

$ jest
 PASS  ./firebase.test.js
  ✓ function test (1334ms)

  console.log firebase.test.js:18
    FUNCTIONS result: { word: 'hellooo' }

Test Suites: 1 passed, 1 total
Tests:       1 passed, 1 total
Snapshots:   0 total
Time:        2.785s, estimated 3s
Ran all test suites.
✨  Done in 4.38s.

I also tried to call an invalid function name and it also finishes (with an error) in about 4s.

Is there something I can change to get the results you're seeing?

[google-oss-bot]

Hey @minism. We need more information to resolve this issue but there hasn't been an update in 5 weekdays. I'm marking the issue as stale and if there are no new updates in the next 5 days I will close it automatically.

If you have more information that will help us get to the bottom of this, just add a comment!

[google-oss-bot]

Hey @minism. We need more information to resolve this issue but there hasn't been an update in 5 weekdays. I'm marking the issue as stale and if there are no new updates in the next 5 days I will close it automatically.

If you have more information that will help us get to the bottom of this, just add a comment!

[google-oss-bot]

Since there haven't been any recent updates here, I am going to close this issue.

@minism if you're still experiencing this problem and want to continue the discussion just leave a comment here and we are happy to re-open this.

[minism]

@hsubox76 Interesting, it is possible we are on different node versions as well.

I created a repository that contains the minimal code to reproduce the issue, it just tries to call a function that doesnt exist, inside of an async function: https://github.com/minism/firebase-timeout-repro

Run it with:

time API_KEY=<FIREBASE_KEY> node index.js

Observe the javascript time log showing the request returns quickly, however (at least on my machine), the process stays open for another 70 seconds before returning to the shell.

I can repro this with both node v8.17.0 and node v10.19.0, both on OSX.