Request never completes - Node async bug

[jeremydrichardson]

Describe the bug
This is an intermittent bug that is related to an async timing issue inherent in Node.

When we make a call to the same FileMaker file in short succession, one of the requests never finishes. This is due to a problem with a promise never resolving or rejecting.

Expected behavior
Request should return with the results of the FileMaker server. The promise should either resolve or reject.

Code Examples
I tracked the bug down to the watcher method on the agent model.

if (!global.FMS_API_CLIENT.WATCHERS[this.global]) {
      const WATCHER = setTimeout(
        function watch() {

What happens is on the second request, the watch with this.global uuid actually exists so it doesn't create a new watcher.

However, the problem is that later on in the watcher, this.pending.length is 0 meaning the watcher is destroyed and the second request never completes.

if (this.queue.length === 0 && this.pending.length === 0) {
            clearTimeout(global.FMS_API_CLIENT.WATCHERS[this.global]);
            delete global.FMS_API_CLIENT.WATCHERS[this.global];
          } else {
            setTimeout(watch.bind(this), this.delay);
          }

Therefore this.resolve() is never called and the promise is left in an unresolved state.

What is being hard to track down is how the watcher can exist if it appears that the second request is not in the pending array. The only explanation is that there is some weird timing issue happening in the Node event loop where things don't line up the way they should.

Tests
Working on this now. Hard to reproduce since it's timing based and therefore intermittent.

Additional context
I'm wondering if there is a better way to deal with the request in the queue/pending than a setTimeout that gets renewed or torn down? Did you every look at the possibility of using Node's event emitter system instead?

One potential solution would be to make the watcher unique for each request

global.FMS_API_CLIENT.WATCHERS[`${this.global}-${some other unique identifier from the request}`] = WATCHER;

Would have to figure out what the unique identifier would be and if there are other repercussions of having individual watchers for each request. Probably won't even need that this.global for the watcher. That seems to be there to reuse the watcher but I'm actually not sure what situation that would ever happen, except for the one I'm experiencing that is a bug.

[jeremydrichardson]

So looks like I got to the bottom of the issue finally.

What was actually happening was that 2 separate clients for the same FileMaker file were being created and somehow they were conflicting with each other.

A little more background in case it helps anyone:

Normally you would initialize a database connection when the app first runs. Then all requests can count on that database connection being open. However, due to the FileMaker API design, in our case we need to initialize the database using fms-api-client on first request. This is because we have multiple users and we need to login to the FileMaker file with that specific username. If we were to initialize when the app started we'd have a huge number of clients initialized, one for each user. Then because we have multiple files we'd need to do a new client for each user * each file. That gets exponentially huge.

Our idea was to build Express middleware that would check the fms-api-client marpat store to see if there is a client already made for that user/database, and if not, initialize one.

// Check if this client already exists
  const existingClient = await Filemaker.findOne({
    name: `${user}-${database}`,
  });

Conceptually it worked great, however every so often we would get a request that never finished. The issue was that if 2 request came in from the same user for the same file, it would create 2 clients. This was due to the first client not being created when the 2nd request was processed so it thought it needed to create another client.

The answer was a little complicated and required storing each client in the express app.locals variable which would happen instantaneously. Of course it would start a promise so we needed to await any promises before allowing the request to proceed.

Anyway, if anyone is interested in the solution I could DM since we're working on a closed source project.

Hope this helps someone since it was a couple days of troubleshooting to solve!

[daniel-heg]

Hi,
I am struggeling with the same problem for a week now.
It would be great if you could help me with your solution.
What would be the best way to get in contact with you?