0

I have a Node.js web application and I am doing an API call that will cause an overload if I request it more often than once a second. So, I have to pause the API call with ~1 sec between every call. It proves to be more difficult than it should be.

I currently use this following code:

var i = 0
db.collection('products').get()
   .then(async (querySnapshot) => {
   var docs = querySnapshot.docs.map(doc => doc);  
 
   docs.forEach(async (doc) => {  
      i += 1
      setTimeout( () => {                     
         console.log(new Date(), "Zzz", i);
         theApiCall().then((locationData) => {
            let result = {
               'location': {
                  'country': result,
               }
            }                                         
         })                   
       }, i * 1500)
   })
})

This works fine for a in my local Mac (Apple M1) with the following log output:

...200 lines of ~1.5 seconds in between and then:
2022-04-23T11:23:51.616Z Zzzz... 957
2022-04-23T11:23:53.117Z Zzzz... 957
2022-04-23T11:23:54.615Z Zzzz... 957
2022-04-23T11:23:56.116Z Zzzz... 957
2022-04-23T11:30:30.245Z Zzzz... 957
2022-04-23T11:30:30.247Z Zzzz... 957
2022-04-23T11:30:30.248Z Zzzz... 957
2022-04-23T11:30:30.250Z Zzzz... 957
node:internal/process/promises:246
          triggerUncaughtException(err, true /* fromPromise */);
          ^

Error: 4 DEADLINE_EXCEEDED: Deadline exceeded
    at Object.callErrorFromStatus (/Users/Christoffer/projects/node/apiapplication//node_modules/@grpc/grpc-js/build/src/call.js:31:26)
    at Object.onReceiveStatus (/Users/Christoffer/projects/node/apiapplication//node_modules/@grpc/grpc-js/build/src/client.js:180:52)
    at Object.onReceiveStatus (/Users/Christoffer/projects/node/apiapplication//node_modules/@grpc/grpc-js/build/src/client-interceptors.js:365:141)
    at Object.onReceiveStatus (/Users/Christoffer/projects/node/apiapplication//node_modules/@grpc/grpc-js/build/src/client-interceptors.js:328:181)
    at /Users/Christoffer/projects/node/apiapplication//node_modules/@grpc/grpc-js/build/src/call-stream.js:182:78
    at processTicksAndRejections (node:internal/process/task_queues:78:11)
    at runNextTicks (node:internal/process/task_queues:65:3)
    at processTimers (node:internal/timers:497:9)
Caused by: Error
    at WriteBatch.commit (/Users/Christoffer/projects/node/apiapplication//node_modules/@google-cloud/firestore/build/src/write-batch.js:414:23)
    at DocumentReference.set (/Users/Christoffer/projects/node/apiapplication//node_modules/@google-cloud/firestore/build/src/reference.js:351:14)
    at /Users/Christoffer/projects/node/apiapplication//server.js:1400:120
    at runMicrotasks (<anonymous>)
    at processTicksAndRejections (node:internal/process/task_queues:96:5) {
  code: 4,
  details: 'Deadline exceeded',
  metadata: Metadata { internalRepr: Map(0) {}, options: {} },
  note: 'Exception occurred in retry method that was not classified as transient'

The error message in itself is not so interesting as I believe it has to do with the API getting too many calls and thus throws a rejection (?).

However, when I run this at Cloud Run (Google Cloud Platform), it quickly seems to completely ignore the setTimeout - and does so intermittently:

2022-04-24T22:01:54.367Z Zzzz... 2966
 2022-04-24T22:01:54.370Z Zzzz... 2966
 2022-04-24T22:01:54.373Z Zzzz... 2966
 2022-04-24T22:01:54.374Z Zzzz... 2966
 2022-04-24T22:01:54.375Z Zzzz... 2966
 2022-04-24T22:01:54.437Z Zzzz... 2966
 2022-04-24T22:01:56.688Z Zzzz... 2966
 2022-04-24T22:01:59.300Z Zzzz... 2966
2022-04-24T22:01:59.302Z Zzzz... 2966
2022-04-24T22:02:00.545Z Zzzz... 2966

Why is the setTimeout behaving so odd ("untrustworthy")? What can I do to really force a pause here that will work on GCP as well?

What strikes me as very odd as well is: Why is i always 957 (2966 respectively)? Shouldn't this be incremented (1,2..n)? This could possibly affect how the timeouts are being spread out and cause the API rejection.

Wayne
  • 4,760
  • 1
  • 24
  • 24
Christoffer
  • 2,271
  • 3
  • 26
  • 57
  • 1
    The forEach loop has already completely by the time any setTimeout callbacks run, thus `i` is at its final value inside the callback: https://stackoverflow.com/questions/11488014/asynchronous-process-inside-a-javascript-for-loop -- It won't fix your issues though, just a note. – danneu Apr 24 '22 at 22:44
  • You have a race condition. It sounds to be as though all 957 async threads are spooling up and incrementing i before even the first is able to move to the next command which is setTimeout. – S. Walker Apr 25 '22 at 00:25
  • 1
    I’m sorry, I mis-interpreted, but the concept remains the same. Multiple threads are incrementing i before even the first can reach the setTimeout method. However, the reason i is always 2966 is because your logging it’s value inside of the setTimeout, which does mean all 957 threads have incremented i before it’s ever logged. – S. Walker Apr 25 '22 at 00:31

0 Answers0