pino: Inconsistent Error logging

I’ve observed a few inconsistencies in logging of Error objects.

code

const pino = require('pino')({level: 'debug'})
const verror = require('verror')

let err1 = new Error('err1')
console.error(err1)
pino.error(err1)
pino.error({ err1 })

output:

Error: err1
    at Object.<anonymous> (/Users/jcalderon/temp/temp2/index.js:5:12)
    at Module._compile (internal/modules/cjs/loader.js:701:30)
    at Object.Module._extensions..js (internal/modules/cjs/loader.js:712:10)
    at Module.load (internal/modules/cjs/loader.js:600:32)
    at tryModuleLoad (internal/modules/cjs/loader.js:539:12)
    at Function.Module._load (internal/modules/cjs/loader.js:531:3)
    at Function.Module.runMain (internal/modules/cjs/loader.js:754:12)
    at startup (internal/bootstrap/node.js:283:19)
    at bootstrapNodeJSCore (internal/bootstrap/node.js:622:3)
{"level":50,"time":1554858902091,"pid":13788,"hostname":"MLP-0U8HV2H","msg":"err1","stack":"Error: err1\n    at Object.<anonymous> (/Users/jcalderon/temp/temp2/index.js:5:12)\n    at Module._compile (internal/modules/cjs/loader.js:701:30)\n    at Object.Module._extensions..js (internal/modules/cjs/loader.js:712:10)\n    at Module.load (internal/modules/cjs/loader.js:600:32)\n    at tryModuleLoad (internal/modules/cjs/loader.js:539:12)\n    at Function.Module._load (internal/modules/cjs/loader.js:531:3)\n    at Function.Module.runMain (internal/modules/cjs/loader.js:754:12)\n    at startup (internal/bootstrap/node.js:283:19)\n    at bootstrapNodeJSCore (internal/bootstrap/node.js:622:3)","type":"Error","v":1}
{"level":50,"time":1554859690038,"pid":13967,"hostname":"MLP-0U8HV2H","err1":{},"v":1}

• The first output is the console output for comparison.
• In the second output, pino is logging the Error.message as as msg, which is fine to stay consistent with other messages in pino, but I wonder if it’s best to log to both msg and message. There’s an example further down where logging both are logged at the same time, but it doesn’t happen in this case here.
• In the third log statement, I nested the Error myself in an object to avoid using the external library. The results are the same (empty object for the Error).

code:

let err2 = new verror.VError(err1, 'err2')
console.error(err2)
pino.error(err2)

output:

{ VError: err2: err1
    at Object.<anonymous> (/Users/jcalderon/temp/temp2/index.js:9:12)
    at Module._compile (internal/modules/cjs/loader.js:701:30)
    at Object.Module._extensions..js (internal/modules/cjs/loader.js:712:10)
    at Module.load (internal/modules/cjs/loader.js:600:32)
    at tryModuleLoad (internal/modules/cjs/loader.js:539:12)
    at Function.Module._load (internal/modules/cjs/loader.js:531:3)
    at Function.Module.runMain (internal/modules/cjs/loader.js:754:12)
    at startup (internal/bootstrap/node.js:283:19)
    at bootstrapNodeJSCore (internal/bootstrap/node.js:622:3)
  jse_shortmsg: 'err2',
  jse_cause:
   Error: err1
       at Object.<anonymous> (/Users/jcalderon/temp/temp2/index.js:5:12)
       at Module._compile (internal/modules/cjs/loader.js:701:30)
       at Object.Module._extensions..js (internal/modules/cjs/loader.js:712:10)
       at Module.load (internal/modules/cjs/loader.js:600:32)
       at tryModuleLoad (internal/modules/cjs/loader.js:539:12)
       at Function.Module._load (internal/modules/cjs/loader.js:531:3)
       at Function.Module.runMain (internal/modules/cjs/loader.js:754:12)
       at startup (internal/bootstrap/node.js:283:19)
       at bootstrapNodeJSCore (internal/bootstrap/node.js:622:3),
  jse_info: {},
  message: 'err2: err1' }
{"level":50,"time":1554859690038,"pid":13967,"hostname":"MLP-0U8HV2H","jse_shortmsg":"err2","jse_cause":{},"jse_info":{},"message":"err2: err1","msg":"err2: err1","stack":"VError: err2: err1\n    at Object.<anonymous> (/Users/jcalderon/temp/temp2/index.js:9:12)\n    at Module._compile (internal/modules/cjs/loader.js:701:30)\n    at Object.Module._extensions..js (internal/modules/cjs/loader.js:712:10)\n    at Module.load (internal/modules/cjs/loader.js:600:32)\n    at tryModuleLoad (internal/modules/cjs/loader.js:539:12)\n    at Function.Module._load (internal/modules/cjs/loader.js:531:3)\n    at Function.Module.runMain (internal/modules/cjs/loader.js:754:12)\n    at startup (internal/bootstrap/node.js:283:19)\n    at bootstrapNodeJSCore (internal/bootstrap/node.js:622:3)","type":"Error","v":1}

• console output again in the first line for reference. *verror library is used, which wraps the original Error in the jse_cause property. When logging using VError instead of Error, pino this time does print out both msg and message (same value) at the root level. However, the jse_cause is still just populated with only an empty string, even though it contains an actual Error object. I was able to print err2.jse_cause.message even though jse_cause is blank in the log.

code:

err1.stdout = '123'
err1.stdin = '456'
err2.stdout = '123'
err2.stdin = '456'
pino.error( { response: err1 })
pino.error( { response: err2 })

output:

{"level":50,"time":1554860583748,"pid":14209,"hostname":"MLP-0U8HV2H","response":{"stdout":"123","stdin":"456"},"v":1}
{"level":50,"time":1554860583748,"pid":14209,"hostname":"MLP-0U8HV2H","response":{"jse_shortmsg":"err2","jse_cause":{"stdout":"123","stdin":"456"},"jse_info":{},"message":"err2: err1","stdout":"123","stdin":"456"},"v":1}

• Modifying the original error to add properties results in the Error and VError objects results in having those additional properties logged. But it looks like the standard “message” and “stack” properties are ignored for both Error and VError.

pino v5.12.2 node v10.15.3