Async library failing under high load

[nidhhoggr]

When the server is under high load the following error is produced:

1|advertis | Error: Callback was already called.
1|advertis |     at /var/www/vhosts/advertising-api/node_modules/async/dist/async.js:903:32
1|advertis |     at /var/www/vhosts/advertising-api/node_modules/async/dist/async.js:3835:13
1|advertis |     at interceptInvocationErrors (/var/www/vhosts/advertising-api/node_modules/strong-remoting/lib/remote-objects.js:692:16)
1|advertis |     at /var/www/vhosts/advertising-api/node_modules/loopback-phase/node_modules/async/lib/async.js:154:25
1|advertis |     at /var/www/vhosts/advertising-api/node_modules/loopback-phase/node_modules/async/lib/async.js:154:25
1|advertis |     at /var/www/vhosts/advertising-api/node_modules/loopback-phase/node_modules/async/lib/async.js:154:25
1|advertis |     at /var/www/vhosts/advertising-api/node_modules/strong-remoting/lib/remote-objects.js:656:7
1|advertis |     at /var/www/vhosts/advertising-api/node_modules/strong-remoting/lib/http-context.js:397:7
1|advertis |     at callback (/var/www/vhosts/advertising-api/node_modules/strong-remoting/lib/shared-method.js:253:5)
1|advertis |     at /var/www/vhosts/advertising-api/common/models/source.js:215:9

This is a result of the next method being called. I checked my model and I am very careful about not calling the method twice, and If I was indeed calling it twice, it would be happening on all requests, not only when the server is stressed out. The issue consistently happens when there is about a load of 1500 concurrent users.

Also to clarify, the code that is responsible to throwing the error at the first level of the stack trace:

  self.phases.run(ctx, function interceptInvocationErrors(err) {
    if (!err) {
        return cb();
    }
    ctx.error = err;
    self.execHooks('afterError', method, scope, ctx, function(hookErr) {
        cb(hookErr || err);
    });
  });

[bajtos]

@nidhhoggr thank you for reporting the error. How can we reproduce it on our side? Could you please provide a small application reproducing the problem per our Bug reporting instructions?

[BerkeleyTrue]

We are also seeing this issue on a brand new server with no load. It is reproducable when creating a new user through the POST /api/user

loopback - 2.38.3
strong-remoting - 2.33.0

[fabien]

@BerkeleyTrue I see you're using Loopback 2.27.0 now - does this mean this version is unaffected?

I've yet to see this error, but is there any chance it's actually the result of an (app) error not being handled correctly inside Strong Remoting?

[BerkeleyTrue]

@fabien With 2.27 I can no longer reproduce the error.

I'm not sure what would be the cause of the error. We are currently running 2.27 in production under heavy load without issue.

[BerkeleyTrue]

I believe the issue stems from this commit: eb2a08c

The previous behavior for remoteMethod hooks to meant that a promise would resolve and prevent the next hooks from running.

In our case, our code was written long before promise support was making it's way into LB. We have a rule that all function paths must end with a return. So, when invoking other methods that return promises, we would naturally return promises as part of the afterRemote hook.

Here we check if an email already exist when a user attempts to create an account: https://github.com/freeCodeCamp/freeCodeCamp/blob/d51474f6829e6549f0a156ca9ef548d8fbf16c8e/common/models/user.js#L166
If not, we call the next handler, then the promises then'd by the execStack function resolves and execStack is run again, since the stack has been flushed the next handler is called a second time causing async to throw an error. Since this happens after two promise resolves the stack trace and error message is entirely unhelpful.

I'm not 100% why this worked fine before that commit above but I'm pretty sure this is the culprit. It may be prudent to add something to the docs (2.0 and 3.0) indicating that the user should take care when mixing returned promises and calling the next handler directly (as well as using redirect and send). Maybe a check to see if the execHooks was already called by current handler within the then and throwing an error to the user pointing them to the fix.

[bajtos]

@BerkeleyTrue thank you for finding the root cause of the problem! I am able to reproduce it with the following beforeRemote hook:

Product.beforeRemote('create', (ctx, _, next) => {
  next();
  return Promise.resolve();
});

Maybe a check to see if the execHooks was already called by current handler within the then and throwing an error to the user pointing them to the fix.

That sounds like a good idea to me. Would you like to contribute this improvement yourself?