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

logger.error(new Error) behaves differently to logger.error({ err: new Error }) #579

Open
richardscarrott opened this Issue Jan 11, 2019 · 5 comments

Comments

Projects
None yet
4 participants
@richardscarrott
Copy link

richardscarrott commented Jan 11, 2019

I'm seeing different behaviour when passing an Error instance directly as the mergingObject when compared to passing it as a nested err property, e.g.

Given this Error:

const cause = new Error('b0rked');
const error = new VError({ cause }, 'Something went wrong');
// VError simply nests Errors on ‘jse_cause’
assert.strictEqual(error.jse_cause, cause);

We can see that nested errors aren't serialised when passing error as the mergingObject:

logger.error(error, 'Something went wrong');

// Outputs:
{
    "level": 50,
    "time": 1547247913525,
    "msg": "Something went wrong",
    "pid": 963,
    "hostname": "d5c8fec6d4ea",
    "name": "orders",
    "type": "Error",
    "stack": "VError: Something went wrong: b0rked\n    at Object.<anonymous> (/usr/src/app/src/index.js:39:15)\n    at Module._compile (module.js:653:30)\n    at Object.Module._extensions..js (module.js:664:10)\n    at Module.load (module.js:566:32)\n    at tryModuleLoad (module.js:506:12)\n    at Function.Module._load (module.js:498:3)\n    at Function.Module.runMain (module.js:694:10)\n    at startup (bootstrap_node.js:204:16)\n    at bootstrap_node.js:625:3",
    "jse_shortmsg": "Something went wrong",
    "jse_cause": {}, // Missing
    "jse_info": {},
    "message": "Something went wrong: b0rked",
    "v": 1
}

However when nesting on an err prop we can see nested errors are serialised:

logger.error({ err: error } , 'Something went wrong');

{
    "level": 50,
    "time": 1547248677531,
    "msg": "Something went wrong",
    "pid": 975,
    "hostname": "d5c8fec6d4ea",
    "name": "orders",
    "err": {
        "type": "VError",
        "message": "Something went wrong: b0rked",
        "stack": "VError: Something went wrong: b0rked\n    at Object.<anonymous> (/usr/src/app/src/index.js:39:15)\n    at Module._compile (module.js:653:30)\n    at Object.Module._extensions..js (module.js:664:10)\n    at Module.load (module.js:566:32)\n    at tryModuleLoad (module.js:506:12)\n    at Function.Module._load (module.js:498:3)\n    at Function.Module.runMain (module.js:694:10)\n    at startup (bootstrap_node.js:204:16)\n    at bootstrap_node.js:625:3",
        "jse_shortmsg": "Something went wrong",
        // Here you can see jse_cause is also serialized
        "jse_cause": {
            "type": "Error",
            "message": "b0rked",
            "stack": "Error: b0rked\n    at Object.<anonymous> (/usr/src/app/src/index.js:38:15)\n    at Module._compile (module.js:653:30)\n    at Object.Module._extensions..js (module.js:664:10)\n    at Module.load (module.js:566:32)\n    at tryModuleLoad (module.js:506:12)\n    at Function.Module._load (module.js:498:3)\n    at Function.Module.runMain (module.js:694:10)\n    at startup (bootstrap_node.js:204:16)\n    at bootstrap_node.js:625:3"
        },
        "jse_info": {},
        "name": "VError"
    },
    "v": 1
}

I know serialising nested errors is a newer feature but I was surprised these don't go through the same serialiser?

Tbh, I've struggled to find any documentation re: the behaviour of passing different types of mergingObjects to the log functions -- from what I can tell there's a special case for Error, ClientRequest, and ServerResponse.

Is there a desire to document these special cases or perhaps even provide an option to remove them?

@richardscarrott richardscarrott changed the title `logger.error(new Error)` behaves differently to `logger.error({ err: new Error })` logger.error(new Error) behaves differently to logger.error({ err: new Error }) Jan 11, 2019

@mcollina

This comment has been minimized.

Copy link
Member

mcollina commented Jan 12, 2019

They don't pass through the same path, mainly because of how the final log line is constructed for perf reasons.

I'd be happy to review a PR that does not regress our benchmarks for this. Otherwise we can just document the current behavior. Would you like to send a PR?

@richardscarrott

This comment has been minimized.

Copy link
Author

richardscarrott commented Jan 13, 2019

I don't have the time right now but will try to come back around to this when I next get some spare time 👍

@sheldhur

This comment has been minimized.

Copy link

sheldhur commented Jan 21, 2019

logger.error({ err: error }); not serialize all native props of errors.

class BaseError extends Error {
  constructor(message) {
    super(message);
    this.name = 'SequelizeBaseError';
    Error.captureStackTrace(this, this.constructor);
  }
}

class TestError extends BaseError {
  constructor(message) {
    super(message + new Date().valueOf());
    this.name = 'SequelizeBaseError';
    this.nativeError = new Error('test');
    this.customError = new BaseError('test');
    Error.captureStackTrace(this, this.constructor);
  }
}

const testLogger = pino();
const errors = [
  new RangeError('test'),
  new ReferenceError('test'),
  new SyntaxError('test'),
  new TypeError('test'),
  new EvalError('test'),
  new URIError('test'),
  new BaseError('test'),
  new TestError('TestError'),
];

errors.map((e) => {
  e.stack = e.stack.substr(0, 40);
  testLogger.error(e, `Test error ${e.name}`);
  testLogger.error({ error: e }, `Test nested object with error ${e.name}`);
});
{"level":50,"time":1548083417168,"msg":"Test error RangeError","pid":5262,"hostname":"dantooine","type":"Error","stack":"RangeError: test\n    at Object.<anonymou","v":1}
{"level":50,"time":1548081155509,"msg":"Test nested object with error RangeError","pid":5187,"hostname":"dantooine","error":{},"v":1}

{"level":50,"time":1548081155509,"msg":"Test error ReferenceError","pid":5187,"hostname":"dantooine","type":"Error","stack":"ReferenceError: test\n    at Object.<anon","v":1}
{"level":50,"time":1548081155509,"msg":"Test nested object with error ReferenceError","pid":5187,"hostname":"dantooine","error":{},"v":1}

{"level":50,"time":1548081155510,"msg":"Test error SyntaxError","pid":5187,"hostname":"dantooine","type":"Error","stack":"SyntaxError: test\n    at Object.<anonymo","v":1}
{"level":50,"time":1548081155510,"msg":"Test nested object with error SyntaxError","pid":5187,"hostname":"dantooine","error":{},"v":1}

{"level":50,"time":1548081155510,"msg":"Test error TypeError","pid":5187,"hostname":"dantooine","type":"Error","stack":"TypeError: test\n    at Object.<anonymous","v":1}
{"level":50,"time":1548081155510,"msg":"Test nested object with error TypeError","pid":5187,"hostname":"dantooine","error":{},"v":1}

{"level":50,"time":1548081155510,"msg":"Test error EvalError","pid":5187,"hostname":"dantooine","type":"Error","stack":"EvalError: test\n    at Object.<anonymous","v":1}
{"level":50,"time":1548081155510,"msg":"Test nested object with error EvalError","pid":5187,"hostname":"dantooine","error":{},"v":1}

{"level":50,"time":1548081155510,"msg":"Test error URIError","pid":5187,"hostname":"dantooine","type":"Error","stack":"URIError: test\n    at Object.<anonymous>","v":1}
{"level":50,"time":1548081155510,"msg":"Test nested object with error URIError","pid":5187,"hostname":"dantooine","error":{},"v":1}

{"level":50,"time":1548081155511,"msg":"Test error SequelizeBaseError","pid":5187,"hostname":"dantooine","type":"Error","stack":"SequelizeBaseError: test\n    at Object.<","name":"SequelizeBaseError","v":1}
{"level":50,"time":1548081155511,"msg":"Test nested object with error SequelizeBaseError","pid":5187,"hostname":"dantooine","error":{"name":"SequelizeBaseError"},"v":1}

{"level":50,"time":1548081155511,"msg":"Test error SequelizeBaseError","pid":5187,"hostname":"dantooine","type":"Error","stack":"SequelizeBaseError: TestError15480811554","name":"SequelizeBaseError","nativeError":{},"customError":{"name":"SequelizeBaseError"},"v":1}
{"level":50,"time":1548081155511,"msg":"Test nested object with error SequelizeBaseError","pid":5187,"hostname":"dantooine","error":{"name":"SequelizeBaseError","nativeError":{},"customError":{"name":"SequelizeBaseError"}},"v":1}
@davidmarkclements

This comment has been minimized.

Copy link
Member

davidmarkclements commented Jan 21, 2019

@sheldhur change

testLogger.error({ error: e }, `Test nested object with error ${e.name}`);

to

testLogger.error({ err: e }, `Test nested object with error ${e.name}`);

This is because Errors have to have their own serializer, see http://getpino.io/#/docs/api?id=serializers-object

Or if you'd like to support the error property, use use the option referenced like so

const logger = pino({serializers: {error: pino.stdSerializers.err})
@davidmarkclements

This comment has been minimized.

Copy link
Member

davidmarkclements commented Jan 21, 2019

additionally if there's anything you don't like about the functionality, you can write your own serializer for errors

you can use the global serializer (http://getpino.io/#/docs/api?id=serializerssymbolfor39pino39-function) to override error serializing when it's not nested as well.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment