"Unhandled error" logged for errors that have been handled correctly (e.g. a validation error)

[PaddyMann]

Description of feature (or steps to reproduce if bug)

With the introduction of strong-error-handler in 3.0, we're seeing validation and access errors logging an "Unhandled error" to console. We consider the error to have been handled correctly, and so would like an easy way to suppress these messages for certain error codes (potentially all 4xx). I think this should be the default behavior - and at least easy to configure.

You can see the "unhandled error" being recorded here: https://github.com/strongloop/strong-error-handler/blob/master/lib/logger.js

You can find some extra context in this Google Groups discussion)

Link to sample repo to reproduce issue (if bug)

Instructions to replicate provided by Buck Bito in the Google Groups discussion

The quick test to reproduce with 2.38.0 or 3.2.1:

1. Use lb to create a fresh "api-server (A LoopBack API server with local User auth)"
2. cd into the project dir
3. node . (to start app)
4. Open API explorer in browser
5. Go to User > GET /Users and "Try it out!"

Expected result

Familiar error response body in the Explorer.

Actual result (if bug)

Familiar error response body in the Explorer and Unhandled Error in the console.

Additional information (Node.js version, LoopBack version, etc)

[doublemarked]

These errors can be suppressed by disabling the error handler's logging, by setting log: false in your middleware.json file. Per the README:

If true, all errors are printed via console.error, including an array of fields (custom error properties) that are safe to include in response messages (both 4xx and 5xx).

[PaddyMann]

I've tweaked my post above to indicate it's a feature request rather than a bug, and that - while I would prefer this to be the default behavior - it should at least be customizable.

The log: false option is weak - it hides both server and client errors. We want to see server errors but not client errors, and I suspect this would be what a large number of other users would want / expect to see as well.

The current workaround of creating your own error-handler isn't great. strong-error-handler does a great job of handling numerous edge cases which you'd basically have to copy/reimplement (unless I'm missing some way to build on it). However, this is the current route we've taken.

Big thanks to @doublemarked for help here and on the Google Groups thread thus far :)

[doublemarked]

@PaddyMann I think I agree with you, logging 4xx and 5xx errors like they are the same thing is flawed logic. Perhaps the log directive should be expanded to allow you to match which types of errors should be logged. So you can do something like log: { statusCode: "^5", message: "whatever" }

[PaddyMann]

That'd be great.

We'd set it up with something like:

log: [
  {"statusCode": "^4", "mute": true},
]

[PaddyMann]

Hmm, seems that there could be some issues with the wrong status codes being used.

If a method doesn't exist, a 404 is currently returned.

{ Error: Shared class  "xxx" has no method handling GET /xxx }

This should return a 501.

I guess this is a separate issue to be resolved though.

[loopdtw]

Would love to get an update on this as well. I'm using native methods such as create, but if I mute the logs, then I wouldn't even know if it was because of an duplicate id sql error.

On a side note, I'm using strong-error-handler with loopback (as I suspect most others are as well). If we did unmute these, is there any correct way in handling native loopback methods?

[bajtos]

Hello, thank you for reporting this issue and thank you @doublemarked for helping out!

I understand the desire to hide 4xx (client) errors from the console output, I agree it's a reasonable request.

OTOH, there is also a good argument for logging both 4xx and 5xx errors too: When users encounter an unexpected 4xx error in the client and call the support to get the problem resolved, they are usually not able to provide much information. Also strong-error-handler is intentionally hiding sensitive informations from the HTTP responses. As a result, most of the useful information needed to troubleshoot the problem will be lost if it is not logged at the server.

As has been already said in the mailing list and in our docs, it's possible to use strong-error-handler to format the HTTP error responses and use custom error logger at the same time. Just load your error-logging middleware before strong-error-handler.

// server/middleware.json
{
  // ...
  "final:after": {
    "./middleware/error-logger": {},
    "strong-error-handler": {
      "params": {
        "log": false,
      }
    }
  }
}

// server/middleware/error-logger
module.exports = function createErrorLogger(options) {
  return function logError(err, req, res, next) {
    // your custom error-logging logic goes here

    const status = err.status || err.statusCode;
    if (status >= 500) {
      // log only Internal Server errors
      console.log('Unhandled error for request %s %s: %s',
        req.method, req.url, err.stack || err);
    }

    // Let the next error handler middleware
    // produce the HTTP response
    next(err);
  };
}

In the light of the above, I am closing this feature request as rejected.

[luncht1me]

strong-error-handler... idk man.

It'd be nice to use since it seems to be convention.
But literally any remote method I write on a model, will always print 'UNHANDLED ERROR' in the server console, even though I'm clearly handling it and manually passing an error back through.

example:

	/* Remote method that checks if current user is an admin */
	User.isAdmin = function (options, cb) {
		if (options.currentUserId) {
			getRolesForUser(options.currentUserId, function (err, roles) {
				if (err) {
					return cb(err, false);
				} else if (roles.indexOf('$admin') !== -1) {
					return cb(null, true);
				} else {
					return cb(null, false);
				}
			})
		} else {
			return cb({statusCode: 400, message: "no currentUserId found [user isn't authenticated]" }, null);
		}
	};

strong-error-handler shouldn't be saying this is unhanded, I do believe this isn't the intended output. I'm totally cool with it logging the error, but throwing it's own internal error makes me think something is wrong.

It's annoying. For now, I've just disabled the whole middleware.

[luncht1me]

@bajtos

Just to chirp in, this seems more directly related to a bug in loopback itself.
If I disable strong-error-handler completely, and use the base lb3 errorhandling, this same behavior occurs. Even if strong-error-handler is installed, and both debug and log are false, the error will still popup, since the default is taking over.

To have strong-error-handler take over completely, still had to set

"remoting":{
  "rest": {
    "handleErrors": false
...

in config.json as per the migrating from lb2 documentation.

So, it's very possible that if the bug gets fixed within loopback, then it will automatically resolve in this module.

[charlle]

@luncht1me I believe this is related to this function convertNullToNotFoundError in persistedModel.js, which only applies to findOne and findById. I don't receive the logging error when I request a find. I just receive an empty array, so this is consistent with my results. Creating the new Error() object is what causes it.