logger properties dropped when error object provided

[rayalan]

Simple reproduction case (pino 5.8, pino-pretty 2.2.2):

const pino = require('pino');

const pinoLogger = pino();
const log = pinoLogger.child({ project: 'my-project' });

log.error('This case works as expected');

try {
    throw new Error('A thrown error');
} catch (error) {
    log.error(error, 'This case does not work');
}

Then running node example.js | pino-pretty gives this (note the lack of a my-project field in the second log message):

[1540094314133] ERROR (87649 on redacted): This case works as expected
    project: "my-project"
[1540094314134] ERROR (87649 on redacted): This case does not work
    Error: A thrown error
        at Object.<anonymous> (redacted/example.js:9:11)
        at Module._compile (module.js:643:30)
        at Object.Module._extensions..js (module.js:654:10)
        at Module.load (module.js:556:32)
        at tryModuleLoad (module.js:499:12)
        at Function.Module._load (module.js:491:3)
        at Function.Module.runMain (module.js:684:10)
        at startup (bootstrap_node.js:187:16)
        at bootstrap_node.js:608:3

Running just node example.js gives the underlying output that I expect with a my-project field in both json messages:

{"level":50,"time":1540094310116,"msg":"This case works as expected","pid":87638,"hostname":"redacted","project":"my-project","v":1}
{"level":50,"time":1540094310117,"msg":"This case does not work","pid":87638,"hostname":"redacted","project":"my-project","type":"Error","stack":"Error: A thrown error\n    at Object.<anonymous> (redacted/example.js:9:11)\n    at Module._compile (module.js:643:30)\n    at Object.Module._extensions..js (module.js:654:10)\n    at Module.load (module.js:556:32)\n    at tryModuleLoad (module.js:499:12)\n    at Function.Module._load (module.js:491:3)\n    at Function.Module.runMain (module.js:684:10)\n    at startup (bootstrap_node.js:187:16)\n    at bootstrap_node.js:608:3","v":1}

[mcollina]

Thanks for reporting! You are right, we should probably include all properties in those errors. Would you like to send a PR?

[rayalan]

I'll take a pass at it...

Digging into it a little, the problem appears to be this section, which gates printing the logger properties based on { errorProps: '*' }:

        if (errorProps[0] === '*') {
          // print all log props excluding 'excludedProps'
          propsForPrint = Object.keys(log).filter((prop) => excludedProps.indexOf(prop) < 0)
        } else {
          // print props from 'errorProps' only
          // but exclude 'excludedProps'
          propsForPrint = errorProps.filter((prop) => excludedProps.indexOf(prop) < 0)
        }

(And in the test I wrote, if I do const pretty = prettyFactory({ errorProps: '*' }), then both the log properties and extra error properties appear.)

So it looks like this behavior emerges from the fact that in the prettifier, there is no difference between between logger properties and error properties. I wonder then if this more of documentation issue:

• Document that there are two determinations of what an error is: The errorLikeObjectKeys option, which determines properties are handled as errors at any depth. And then There is the log.type == ERROR with stack that triggers whether errorProps is applied or not.
• Document that errorProps is a bit misleading, since it applies not to an error object, but to a top-level log error with a stack, and the properties specified need to include logger properties of note, not just error properties.

I can imagine other approaches, but most of them aren't backward compatible. Any thoughts? Have I properly understood the intent of the code?

[mcollina]

I'm kind of lost already, can you please make a concrete proposal to fix this? This PR introduced the flag https://github.com/pinojs/pino/pull/372. I think the best approach would be to support errorProps: '*' also on top-level errors, but I have not investigated this issue.

[rayalan]

@mcollina

• There is already top-level support for errorProps: * on top level errors.
• Sorry; I thought the proposal to update the documentation in two ways because the documentation wasn't clear on the definition of an error being different at the top level was pretty concrete; I'm not sure how to make that more concrete without actually doing it, and I don't want to go to the effort of writing code/documentation if there isn't agreement on what the right fix is.

[mcollina]

From you said, it seems that the implementation of errorProps was not complete. Did I understand it wrong?

[rayalan]

It depends on how you define complete. I would say that the documented behavior of errorProps is not what I expected. When I was learning about pino-pretty, Here's the documentation from the README that seemed to pertain:

--errorProps (-e): When formatting an error object, display this list of properties. The list should be a comma separated list of properties Default: ''.
--errorLikeObjectKeys (-k): Define the log keys that are associated with error like objects. Default: err,error.

I drew these conclusions from reading that documentation:

• pino-pretty can recognize error objects
• it does so by the field name (by default, error and error)
• it won't add properties of the error object except those specified by --errorProps

Here are the conclusions that I believe are true based on code, but don't see as obvious from the above documentation:

• The top level object will be determined to be an error object if it has a stack property and the log type is Error.
• The logger properties are considered to be properties of the top level object.
• Therefore, the logger properties are excluded from objects with a stack logged at the error level unless the logger properties or * is specified for the --errorProps field.

[mcollina]

What do you propose?

[webstacker]

I was having a similar issue: https://github.com/pinojs/express-pino-logger/issues/34#issuecomment-508148208

I know the following doesn't address the issue directly, but for anyone else, this can be worked around to an extent but wrapping the error in an object with an "err" property e.g.

const pinoLogger = require('pino')({
    level: 'debug',
    prettyPrint: {
        levelFirst: true,
        colorize: true,
        translateTime: true
    }
});
const log = pinoLogger.child({ project: 'my-project' });

log.error('This case works as expected');

try {
    const err = new Error('A thrown error');

    err.customProperty = 123;

    throw err;
} catch (error) {
    log.error(error, 'This case does not work');
    log.error({err: error}, 'This case does work');
}