Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Unhandled error for request when sending error to callback #3356

Closed
cfree opened this issue Apr 12, 2017 · 36 comments
Closed

Unhandled error for request when sending error to callback #3356

cfree opened this issue Apr 12, 2017 · 36 comments
Labels

Comments

@cfree
Copy link

cfree commented Apr 12, 2017

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
├── loopback@3.6.0
├── loopback-boot@2.24.0
├── loopback-component-explorer@4.2.0
@bitmage
Copy link
Contributor

bitmage commented May 17, 2017

I'm getting this as well.

$ npm ls loopback
└── loopback@2.38.3

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
Copy link

luncht1me commented Jun 20, 2017

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
Copy link

smyth64 commented Jun 21, 2017

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

@lehni
Copy link
Contributor

lehni commented Jul 15, 2017

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
Copy link

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
Copy link
Contributor

I also have this problem ..

@sumnerevans
Copy link

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
Copy link

stale bot commented Oct 1, 2017

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.

@stale stale bot added the stale label Oct 1, 2017
@cfree
Copy link
Author

cfree commented Oct 5, 2017

^^^

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...

@stale stale bot removed the stale label Oct 5, 2017
@stychu
Copy link

stychu commented Oct 10, 2017

any solution to this problem ?

@CFreeAetna
Copy link

Promises in Loopback appears to be in ongoing development: #418 (comment)

@grs4
Copy link

grs4 commented Oct 21, 2017

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
Copy link

stale bot commented Dec 20, 2017

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.

@stale stale bot added the stale label Dec 20, 2017
@choychris
Copy link

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 ?

@stale stale bot removed the stale label Dec 27, 2017
@Munmw
Copy link

Munmw commented Jan 3, 2018

yeah. same issue here as well.

@xavierchow
Copy link

I have the same issue,

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

├── loopback@3.11.1
├── loopback-boot@2.26.1
├── loopback-component-explorer@4.2.0

@robwilson1
Copy link

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.

├── loopback@3.16.2
├── loopback-boot@2.26.1
├── loopback-component-explorer@4.2.0
├── loopback-connector-mongodb@3.2.1
├── loopback-context@3.3.0

@xavierchow
Copy link

As a workaround, I ended up with setting log: false as per loopbackio/strong-error-handler#40 (comment).

@SoilChang
Copy link

same issue

@shivamgupta211
Copy link

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

@stale
Copy link

stale bot commented May 13, 2018

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.

@stale stale bot added stale and removed stale labels May 13, 2018
@dhmlau dhmlau added the bug label May 24, 2018
@bajtos
Copy link
Member

bajtos commented May 28, 2018

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 loopbackio/strong-error-handler#40, I proposed an improvement in loopbackio/strong-error-handler#54 (comment).

Closing this issue as a duplicate.

@bajtos bajtos closed this as completed May 28, 2018
@bajtos
Copy link
Member

bajtos commented May 28, 2018

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
Copy link

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
Copy link
Member

bajtos commented May 30, 2018

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
Copy link
Contributor

bitmage commented May 30, 2018 via email

@bajtos
Copy link
Member

bajtos commented May 31, 2018

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
Copy link

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

@bitmage
Copy link
Contributor

bitmage commented Jun 4, 2018 via email

@iyobo
Copy link

iyobo commented Nov 2, 2018

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
Copy link

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

@kennethpdev
Copy link

kennethpdev commented Feb 26, 2020

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
Copy link

SBO-Fooderise commented Mar 21, 2020

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
Copy link

herbecon commented Sep 9, 2020

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
Copy link

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

@juned1998
Copy link

any updates on this?

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Projects
None yet
Development

No branches or pull requests