Loopback: Unhandled error for request when sending error to callback

[cfree]

Description/Steps to reproduce

While testing responses in Loopback using promises, it was noticed that Loopback reports unhandled errors to the console despite the request succeeding.

Example:

Test.sampleRemoteMethod1 = (callback) => {
    const customErr = new Error('This does not work');
    customErr.status = 501;

    callback(customErr);
  };

results in:

Unhandled error for request GET /tests/1: Error: This does not work
    at Function.Test.sampleRemoteMethod1 (.../server/models/test.js:28:23)
    at SharedMethod.invoke (.../node_modules/strong-remoting/lib/shared-method.js:270:25)
    at HttpContext.invoke (.../node_modules/strong-remoting/lib/http-context.js:297:12)
    at phaseInvoke (.../node_modules/strong-remoting/lib/remote-objects.js:649:9)
    at runHandler (.../node_modules/strong-remoting/node_modules/loopback-phase/lib/phase.j
    at iterate (.../node_modules/strong-remoting/node_modules/loopback-phase/node_modules/a
    at Object.async.eachSeries (.../node_modules/strong-remoting/node_modules/loopback-phas
    at runHandlers (.../node_modules/strong-remoting/node_modules/loopback-phase/lib/phase.
    at iterate (.../node_modules/strong-remoting/node_modules/loopback-phase/node_modules/a
    at .../node_modules/strong-remoting/node_modules/loopback-phase/node_modules/async/lib/
    at .../node_modules/strong-remoting/node_modules/loopback-phase/node_modules/async/lib/
    at execStack (.../node_modules/strong-remoting/lib/remote-objects.js:494:7)
    at RemoteObjects.execHooks (.../node_modules/strong-remoting/lib/remote-objects.js:498:
    at phaseBeforeInvoke (.../node_modules/strong-remoting/lib/remote-objects.js:645:10)
    at runHandler (.../node_modules/strong-remoting/node_modules/loopback-phase/lib/phase.j
    at iterate (.../node_modules/strong-remoting/node_modules/loopback-phase/node_modules/a
    at .../node_modules/strong-remoting/node_modules/loopback-phase/node_modules/async/lib/
    at reportSharedCtorError (.../node_modules/strong-remoting/lib/remote-objects.js:641:5)
    at runHandler (.../node_modules/strong-remoting/node_modules/loopback-phase/lib/phase.j
    at iterate (.../node_modules/strong-remoting/node_modules/loopback-phase/node_modules/a
    at Object.async.eachSeries (.../node_modules/strong-remoting/node_modules/loopback-phas
    at runHandlers (.../node_modules/strong-remoting/node_modules/loopback-phase/lib/phase.
    at iterate (.../node_modules/strong-remoting/node_modules/loopback-phase/node_modules/a
    at Object.async.eachSeries (.../node_modules/strong-remoting/node_modules/loopback-phas
    at Phase.run (.../node_modules/strong-remoting/node_modules/loopback-phase/lib/phase.js
    at .../node_modules/strong-remoting/node_modules/loopback-phase/lib/phase-list.js:256:1
    at iterate (.../node_modules/strong-remoting/node_modules/loopback-phase/node_modules/a
    at .../node_modules/strong-remoting/node_modules/loopback-phase/node_modules/async/lib/
    at .../node_modules/strong-remoting/node_modules/loopback-phase/node_modules/async/lib/
    at Object.async.eachSeries (.../node_modules/strong-remoting/node_modules/loopback-phas
    at runHandlers (.../node_modules/strong-remoting/node_modules/loopback-phase/lib/phase.
    at iterate (.../node_modules/strong-remoting/node_modules/loopback-phase/node_modules/a
    at .../node_modules/strong-remoting/node_modules/loopback-phase/node_modules/async/lib/
    at .../node_modules/strong-remoting/node_modules/loopback-phase/node_modules/async/lib/
    at .../node_modules/strong-remoting/lib/remote-objects.js:625:7
    at _combinedTickCallback (internal/process/next_tick.js:67:7)
    at process._tickCallback (internal/process/next_tick.js:98:9)

Using promises in the remote method results similarly:

Unhandled error for request GET /tests/3: Error: Still not working
    at requestPromise.then.catch.err (.../server/models/test.js:86:25)
    at process._tickCallback (internal/process/next_tick.js:103:7

I started digging and it seems that something is breaking after the callback has been fired. I created a repo with simplified models and remote methods. For fun, I tried a successful call, with promises (no errors) and without. Using promises, a successful method request gets the UnhandledPromiseRejectionWarning error when a promise successfully finishes.

Example:

Test.sampleRemoteMethod3 = (callback) => {
    const requestPromise = new Promise((resolve, reject) => {
      request('http://aol.com', (err, res, body) => {
        if (err) {
          reject(err);
        } else if (res.statusCode && res.statusCode === 500) {
          return reject(res.statusCode);
        } else {
          resolve(body);
        }
      });
    });

    return requestPromise.then(data => {
      return callback(null, 'This worked');
    })
    .catch(err => {
      const customErr = new Error('Still not working');
      customErr.status = 504;
      return callback(customErr);
    });
  };

Results:

(node:21617) UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: 1): Error: Callback was already called.

Sample repo: https://github.com/cfree/lb-error

Expected result

No errors

Additional information

node -e 'console.log(process.platform, process.arch, process.versions.node)'
  darwin x64 6.8.1

npm ls --prod --depth 0 | grep loopback
├── [email protected]
├── [email protected]
├── [email protected]

[bitmage]

I'm getting this as well.

$ npm ls loopback
└── [email protected]

I get this when I pass an error to done, and also with Loopback's builtin facility for {required: true} parameters on the remote method. It doesn't appear to be actually crashing the server, the log output is just annoying, particularly in my tests.

The status code on the response gets set correctly though - 400 in my case.

[luncht1me]

Super annoying. What's the fix for this? We're in production on loopback 3.8.0 and this is still haunting our server logs.

Like, the docs say to handle errors by passing them back through the remote method's callback.
So, why is it saying unhandled error? c'mon boiz

[smyth64]

I have the same problem =/ Really annoying! Before a few days everything worked fine!

[lehni]

It looks like this is caused in the strong-error-handler module, which is configured through middleware.json. If you set "log": false in its "params", or remove it entirely, then these errors should not appearing in your log files:

  "final:after": {
    "strong-error-handler": {
      "params": {
        "debug": false,
        "log": false
      }
    }
  }

[luncht1me]

Sorry thought I commented on this earlier. Did some digging and seems this error is bubbling up from Loopback itself, and just being caught by this module. As per loopback docs, an error is handled when we pass it through manually in our remote methods. So, hopefully they'll fix it and then this will just go away. 👌

Also, disabling error logs is not a solution. You want to know when you have unhandled errors

[pierreclr]

I also have this problem ..

[sumnerevans]

I've spent some time finding the source of this problem. Here are my findings. There are actually two distinct problems.

1. The first problem applies to test cases 1, 2, and, to some extent, 4 from the sample repo. In strong-globalize/lib/globalize.js:226:

   if (consoleEnabled()) console(msg.message);

   consoleEnabled returns true which causes the error to be logged.

2. The second problem occurs in test case 3 from the sample repo. In async/dist/async.js:903:

   if (fn === null) throw new Error("Callback was already called.");

   Which causes an

   UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: 1): Error: Callback was already called.

   error which is handled by Node itself.

CC: @cfree

[stale[bot]]

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.

[cfree]

^^^

This doesn't seem like an effective bug strategy. It's still a bug even if nobody has addressed (or even triaged it) it yet...

[stychu]

any solution to this problem ?

[CFreeAetna]

Promises in Loopback appears to be in ongoing development: https://github.com/strongloop/loopback/issues/418#issue-38984704

[grs4]

I have the same issue ("Callback was already called.") , while dealing with null object/err with 404 on findOne or findById.
If anyone has workaround solution for this, please post.

[stale[bot]]

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.

[choychris]

I am passing an error intentionally to prevent some creation in 'before save' hook in next(error),
then the Unhandled error pops up in console log. Any solution for this ?

[Munmw]

yeah. same issue here as well.

[xavierchow]

I have the same issue,

npm ls --prod --depth 0 | grep loopback

├── [email protected]
├── [email protected]
├── [email protected]

[phobos101]

Also having this issue which is kinda breaking my error logging flow.

As previous users have mentioned, when a Promise handles a rejection gracefully, my error logging middleware logs the error fine, but then loopback logs it as an unhandled error immediately after.

├── [email protected]
├── [email protected]
├── [email protected]
├── [email protected]
├── [email protected]

[xavierchow]

As a workaround, I ended up with setting log: false as per https://github.com/strongloop/strong-error-handler/issues/40#issuecomment-276178204.

[SoilChang]

same issue

[shivamgupta211]

Please do something about this bug, StrongLoop/Loopback. My servers log files are getting filled with these annoying consoles.

[stale[bot]]

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.

[bajtos]

In a typical LoopBack application, errors are printed to console by strong-error-handler middleware. At the moment, this middleware logs all errors that propagate that far, because we cannot tell what error do you consider as being handled.

Also, when you say that an error is handled, then what do you mean by being handled and which part of your app did handle it? In the example shown in the issue description, the custom remote method converted an error from a client HTTP call into a server-side 501 error. From the point of view of LoopBack, that server-side error was not handled, because no error HTTP response was sent back to the client, instead the remote method passed the error via the callback argument back to LoopBack framework to handle it.

This topic has been already discussed in https://github.com/strongloop/strong-error-handler/issues/40, I proposed an improvement in https://github.com/strongloop/strong-error-handler/issues/54#issuecomment-294847500.

Closing this issue as a duplicate.

[bajtos]

Also a note on returning errors via a Promise. The example in the issue description is converting promises into callbacks, which is unnecessary complex and may have subtle bugs. LoopBack allows remote methods to return a promise directly.

Test.sampleRemoteMethod3 = () => {
    const requestPromise = new Promise((resolve, reject) => {
      request('http://aol.com', (err, res, body) => {
        if (err) {
          reject(err);
        } else if (res.statusCode && res.statusCode === 500) {
          return reject(res.statusCode);
        } else {
          resolve(body);
        }
      });
    });

  return requestPromise
    .then(data => 'This worked');
    .catch(err => {
      const customErr = new Error('Still not working');
      customErr.status = 504;
      return callback(customErr);
    });
};

FWIW, the code could be further simplified by using request-promise-native:

// const request = require('request-promise-native');

Test.sampleRemoteMethod3 = () => {
  const opts = {
    url: 'http://aol.com',
    resolveWithFullResponse: true,
    simple: false,
  };

  return request(opts)
    .then(res => {
       if (res.statusCode && res.statusCode === 500) {
         return Promise.reject(res.statusCode);
      }
      return res.body;
    })
    .catch(err => {
      const customErr = new Error('Still not working');
      customErr.status = 504;
      return callback(customErr);
    });

[yongzhi-chen]

hi @bajtos, i have been going through a few issues related to this issue. Your argument is that we actually dont handle the error, because we just pass it to the callback and it is loopback that handles the error. But on our side, there is no way for us to prematurely end the request and the only way we can do is to pass the error the callback (since in Model.remoteMethod we dont have access to resopnse object). So now the problem is that, we are aware of errors and want to handle them nicely, but we can only propagate them to loopback and strong error handling.

[bajtos]

Thank you @yongzhi-chen for a thoughtful comment.

My concern is that at LoopBack side, how can we tell whether the error received by our callback is something that's intentional on your side (e.g. an error with statusCode set to 404) or just an arbitrary unexpected error forwarded from lower-level layers of your application?

Consider the following code:

MyModel.myRemoteMethod = function(cb) {
  fs.readFile('some-path', function(err, data) {
    if (err) cb(err);
    else cb(null, {data: data});
  });
}

It assumes the file "some-path" exists and can be read by Node.js process. When one of these assumptions fail, the error is propagated through the callback the same way as "handled" errors are.

One idea comes to my mind - most libraries don't set statusCode nor status property on the Error objects they produce. Maybe we can use this difference to distinguish between handled and unhandled errors? The caveat is that loopback-datasource-juggler is aware of HTTP transport and does set e.g. err.statusCode = 404. Would it be a concern if such errors (produced by framework, maybe not considered as handled by the app) were not logged?

Even if we decide to follow this direction, I think we should hide this new feature behind a configuration setting that's disabled by default for backwards compatibility.

Thoughts?

[bitmage]

What if we exposed configuration to filter logs based on the status code?

5xx: true
4xx: false
403: true

Of course anything without a status set becomes a 500.

That would make it easy to understand and more broadly useful, e.g. maybe I want to turn on 404 logging on production if I’m trying to troubleshoot something.

Default could be everything on to be backwards compatible.

On May 30, 2018, at 5:47 AM, Miroslav Bajtoš [e-mail] wrote:

Thank you @yongzhi-chen for a thoughtful comment.

My concern is that at LoopBack side, how can we tell whether the error received by our callback is something that's intentional on your side (e.g. an error with statusCode set to 404) or just an arbitrary unexpected error forwarded from lower-level layers of your application?

Consider the following code:

MyModel.myRemoteMethod = function(cb) {
fs.readFile('some-path', function(err, data) {
if (err) cb(err);
else cb(null, {data: data});
});
}
It assumes the file "some-path" exists and can be read by Node.js process. When one of these assumptions fail, the error is propagated through the callback the same way as "handled" errors are.

One idea comes to my mind - most libraries don't set statusCode nor status property on the Error objects they produce. Maybe we can use this difference to distinguish between handled and unhandled errors? The caveat is that loopback-datasource-juggler is aware of HTTP transport and does set e.g. err.statusCode = 404. Would it be a concern if such errors (produced by framework, maybe not considered as handled by the app) were not logged?

Even if we decide to follow this direction, I think we should hide this new feature behind a configuration setting that's disabled by default for backwards compatibility.

Thoughts?

—
You are receiving this because you commented.
Reply to this email directly, view it on GitHub, or mute the thread.

[bajtos]

What if we exposed configuration to filter logs based on the status code?

• 5xx: true
• 4xx: false
• 403: true

Fair enough. I suppose we can overload the existing log property as follows:

• Log all errors: { "log": true } (already supported - no change)
• No error logging: { "log": false } (already supported - no change)
• Custom logging rules: { "5xx": true, "4xx": false, "403": true } (new feature)

Of course anything without a status set becomes a 500.

Would it make sense to introduce a flag to control this behavior? I.e. to allow app developers to say: treat all errors providing an status code as handled (no logs), but log errors that didn't provide status code, because they are most likely unexpected.

[yongzhi-chen]

^ +1
I think a flag makes sense as well.

[bitmage]

Flag doesn’t make a lot of difference for me, but I won’t complain if it’s there.

On May 31, 2018, at 8:38 AM, yongzhi-chen [e-mail] wrote:

^ +1
I think a flag makes sense as well.

—
You are receiving this because you commented.
Reply to this email directly, view it on GitHub, or mute the thread.

[iyobo]

The easiest way to go about this is to make deliberately bubbled up loopback-style errors and normal, errors be logged under separate groups....instead of both logged under "ERROR".
It's been a little confusing for me trying to clean up my logs.

That way we can turn off whichever we want in the logs.

Maybe We log loopback errors (e.g error objects like those in 'loopback-boom') as NOTICE or a totally custom channel on its own.

Normal JS unformatted errors can maintain the ERROR channel.

ALTERNATIVELY and possibly simpler, We simply remove the phrase "Unhandled error for request" before logging the error as that's really not true. Not every error that hits loopback is unhandled.

Allow the normal JS runtime to be the only thing that uses the phrase "unhandled error".

[slim-hmidi]

I have the same issue here. Is there any progress in that issue or not?

[kennethpdev]

just bumped on this problem. Any other workarounds? I've been looking even at page 2 of google and no joy. Still getting the annoying Unhandled error for request GET error even though its just a simple error test.

const HttpErrors = require('http-errors');
User.verify= (callback) => {
  callback(new HttpErrors.BadRequest('Unknown user.'));
};

Dependencies

"loopback": "^3.26.0",
"loopback-boot": "^3.2.0",
"loopback-component-explorer": "^6.4.0",
"loopback-connector-postgresql": "^3.5.0",

[SBO-Fooderise]

I have loopback 3.22.0 and if you pass a custom error object that has statusCode 5xx to the callback function, the server will take over and respond to client according to the code. Therefore client will not receive the custom error object.

[herbecon]

I have the same issue here with next dependencies:

"loopback": "3.27.0",
"loopback-boot": "^3.3.1",
"loopback-component-explorer": "^6.5.1",

any solution?

[Prashant-Chandel]

I am facing the same on my side.Is there any solution to this

[juned1998]

any updates on this?