Repository: pinojs/pino (js)

Issue:
Improve stack traces for serialized errors in pretty mode
This issue has bugged me for a while.

I often include error objects in log context and to make sure they are properly displayed, I use `pino.stdSerializers.err` or another error serialization tool.

However, those serialized errors stack traces are displayed as a single-line string with new lines converted to visible `\n` characters. While this might be ok for production, it is really suboptimal during development.

For example, given this configuration:

```javascript
const pino = require('pino');

const logger = pino({
  serializers: {
    err: pino.stdSerializers.err,
  }
});

const err = new Error('dummy error');

logger.error({ err });
```

Piping the output of the code above to `pino pretty` gives me:

![one_liner_stack_strace](https://user-images.githubusercontent.com/16565602/37601557-1300b4c8-2b69-11e8-8a04-59a38af5f693.png)

It's quite hard do read a stacktrace like that.

What was intriguing to me was that if I logged the error directly, it'd show a nicely formatted stack trace:

```javascript
logger.error(err);
```
![good_stack_strace](https://user-images.githubusercontent.com/16565602/37601858-d7d017e4-2b69-11e8-8c26-e5f782090b41.png)

---

It would be nice to be able to declare a whitelist of object keys which would be treated as errors by `pino pretty`, properly formatting their `stack` property, as it's already done when logging an `Error` object.

I already have implemented such feature, I can issue a PR at any time if you think this is a good feature for pino.

Pull request:
Improved serialized error stack traces in pretty mode
Fixes #373

## Motivation

Display properly indented multi-line stack-traces for error-like objects in pretty mode.

## Sample code

```javascript
const pino = require('pino');

const logger = pino({
  serializers: {
    err: pino.stdSerializers.err,
    error: pino.stdSerializers.err,
  }
});

const err = new Error('dummy error');

logger.error(err);
logger.error({ err });
logger.error({ error: err });
```

## Current output

![before](https://user-images.githubusercontent.com/16565602/37611818-37112ba4-2b82-11e8-912c-1a58e017e0b6.png)

## Patched output

![after](https://user-images.githubusercontent.com/16565602/37611856-4d08483e-2b82-11e8-8fbb-c5d0999ac486.png)

## Discussion

- I opted to include default values for `errorLikeObjectKeys` prop to be `['err', 'error']`, as these are the most natural object keys for errors. It's possible to change that using the CLI arg `--errorLikeObjectKeys` or passing a `errorLikeObjectKeys` as an option when invoking `pino.pretty()`. However, I'm not sure how to properly document this. Suggestions?


Patch:
diff --git a/bin.js b/bin.js
index 40156bd..62a3179 100755
--- a/bin.js
+++ b/bin.js
@@ -16,9 +16,10 @@ if (arg('-h') || arg('--help')) {
     timeTransOnly: arg('-t'),
     levelFirst: arg('-l'),
     forceColor: arg('-c'),
-    messageKey: messageKeyArg(),
-    dateFormat: dateFormat(),
-    errorProps: errorPropsArg(),
+    messageKey: argWithParam('-m'),
+    dateFormat: argWithParam('--dateFormat'),
+    errorProps: paramToArray(argWithParam('--errorProps')),
+    errorLikeObjectKeys: paramToArray(argWithParam('--errorLikeObjectKeys')),
     localTime: arg('--localTime')
   })).pipe(process.stdout)
   if (!process.stdin.isTTY && !fs.fstatSync(process.stdin.fd).isFile()) {
@@ -35,43 +36,24 @@ function arg (s) {
   return !!~process.argv.indexOf(s)
 }
 
-function messageKeyArg () {
-  if (!arg('-m')) {
+function argWithParam (s) {
+  if (!arg(s)) {
     return
   }
-  var messageKeyIndex = process.argv.indexOf('-m') + 1
-  var messageKey = process.argv.length > messageKeyIndex &&
-    process.argv[messageKeyIndex]
+  var argIndex = process.argv.indexOf(s) + 1
+  var argValue = process.argv.length > argIndex &&
+    process.argv[argIndex]
 
-  if (!messageKey) {
-    throw new Error('-m flag provided without a string argument')
+  if (!argValue) {
+    throw new Error(s + ' flag provided without a string argument')
   }
-  return messageKey
+  return argValue
 }
 
-function dateFormat () {
-  if (!arg('--dateFormat')) {
+function paramToArray (param) {
+  if (!param) {
     return
   }
-  var dateFormatIndex = process.argv.indexOf('--dateFormat') + 1
-  var dateFormat = process.argv.length > dateFormatIndex &&
-    process.argv[dateFormatIndex]
-  if (!dateFormat) {
-    throw new Error('--dateFormat flag provided without a string argument')
-  }
-  return dateFormat
-}
 
-function errorPropsArg () {
-  if (!arg('--errorProps')) {
-    return
-  }
-  var errorPropsIndex = process.argv.indexOf('--errorProps') + 1
-  var errorProps = process.argv.length > errorPropsIndex &&
-    process.argv[errorPropsIndex]
-  if (!errorProps) {
-    throw new Error('--errorProps flag provided without a string argument')
-  }
-  var errorPropsArr = errorProps.split(',')
-  return errorPropsArr
+  return param.split(/\s?,\s?/)
 }
diff --git a/docs/API.md b/docs/API.md
index 0731b92..e787678 100644
--- a/docs/API.md
+++ b/docs/API.md
@@ -126,6 +126,7 @@ Returns a new [logger](#logger) instance.
   * `forceColor` (boolean): if set to `true`, will add color information to the formatted output
   message. Default: `false`.
   * `crlf` (boolean): emit `\r\n` instead of `\n`. Default: `false`.
+  * `errorLikeObjectKeys` (array): error-like objects containing stack traces that should be prettified. Default: `['err', 'error']`.
 
 ### Example:
 ```js
diff --git a/pretty.js b/pretty.js
index 4b61b0d..a00b737 100755
--- a/pretty.js
+++ b/pretty.js
@@ -23,6 +23,13 @@ var standardKeys = [
   'v'
 ]
 
+var defaultErrorLikeObjectKeys = [
+  'err',
+  'error'
+]
+
+var defaultMessageKey = 'msg'
+
 function toTimezoneOffset (aMinTimeoffset) {
   // +/- minute timeoffset
   var tz = aMinTimeoffset || new Date().getTimezoneOffset()
@@ -51,7 +58,9 @@ function withSpaces (value, eol) {
   return lines.join(eol)
 }
 
-function filter (value, messageKey, eol, excludeStandardKeys) {
+function filter (value, messageKey, eol, errorLikeObjectKeys, excludeStandardKeys) {
+  errorLikeObjectKeys = errorLikeObjectKeys || []
+
   var keys = Object.keys(value)
   var filteredKeys = [messageKey]
 
@@ -62,7 +71,31 @@ function filter (value, messageKey, eol, excludeStandardKeys) {
   var result = ''
 
   for (var i = 0; i < keys.length; i++) {
-    if (filteredKeys.indexOf(keys[i]) < 0) {
+    if (errorLikeObjectKeys.indexOf(keys[i]) !== -1) {
+      var arrayOfLines = ('    ' + keys[i] + ': ' + withSpaces(JSON.stringify(value[keys[i]], null, 2), eol) + eol).split('\n')
+
+      for (var j = 0; j < arrayOfLines.length; j++) {
+        if (j !== 0) {
+          result += '\n'
+        }
+
+        var line = arrayOfLines[j]
+
+        if (/^\s*"stack"/.test(line)) {
+          var matches = /^(\s*"stack":)\s*"(.*)",?$/.exec(line)
+
+          if (matches.length === 3) {
+            var indentSize = /^\s*/.exec(line)[0].length + 4
+            var indentation = Array(indentSize + 1).join(' ')
+
+            result += matches[1] + '\n' + indentation +
+              matches[2].replace(/\\n/g, '\n' + indentation)
+          }
+        } else {
+          result += line
+        }
+      }
+    } else if (filteredKeys.indexOf(keys[i]) < 0) {
       result += '    ' + keys[i] + ': ' + withSpaces(JSON.stringify(value[keys[i]], null, 2), eol) + eol
     }
   }
@@ -79,12 +112,15 @@ function pretty (opts) {
   var formatter = opts && opts.formatter
   var dateFormat = opts && opts.dateFormat
   var errorProps = opts && opts.errorProps
+  var errorLikeObjectKeys = opts && opts.errorLikeObjectKeys
   var localTime = opts && opts.localTime
   var levelFirst = opts && opts.levelFirst
   var messageKey = opts && opts.messageKey
   var forceColor = opts && opts.forceColor
   var eol = opts && opts.crlf ? '\r\n' : '\n'
-  messageKey = messageKey || 'msg'
+
+  messageKey = messageKey || defaultMessageKey
+  errorLikeObjectKeys = errorLikeObjectKeys || defaultErrorLikeObjectKeys
 
   var stream = split(mapLine)
   var ctx
@@ -204,7 +240,7 @@ function pretty (opts) {
             if (value[key] instanceof Object) {
               // call 'filter' with 'excludeStandardKeys' = false
               // because nested property might contain property from 'standardKeys'
-              line += key + ': {' + eol + filter(value[key], '', eol, false) + '}' + eol
+              line += key + ': {' + eol + filter(value[key], '', eol, errorLikeObjectKeys, false) + '}' + eol
             } else {
               line += key + ': ' + value[key] + eol
             }
@@ -212,7 +248,7 @@ function pretty (opts) {
         }
       }
     } else {
-      line += filter(value, messageKey, eol)
+      line += filter(value, messageKey, eol, errorLikeObjectKeys)
     }
 
     return line


Test patch:
diff --git a/test/pretty.test.js b/test/pretty.test.js
index af41aaf..85f7152 100644
--- a/test/pretty.test.js
+++ b/test/pretty.test.js
@@ -9,6 +9,7 @@ var writeStream = require('flush-write-stream')
 var fork = require('child_process').fork
 var split = require('split2')
 var hostname = os.hostname()
+var serializers = require('pino-std-serializers')
 
 test('pino transform prettifies', function (t) {
   t.plan(4)
@@ -51,6 +52,7 @@ test('pino pretty force color on flag', function (t) {
 
   instance.info('hello world')
 })
+
 test('pino transform can just parse the dates', function (t) {
   t.plan(1)
   var prettier = pretty({ timeTransOnly: true })
@@ -103,6 +105,80 @@ test('pino transform prettifies Error', function (t) {
   instance.info(err)
 })
 
+function getIndentLevel (str) {
+  return (/^\s*/.exec(str) || [''])[0].length
+}
+
+test('pino transform prettifies Error in property within errorLikeObjectKeys', function (t) {
+  var prettier = pretty({
+    errorLikeObjectKeys: ['err']
+  })
+
+  var err = new Error('hello world')
+  var expectedTraces = err.stack.split('\n').slice(1)
+
+  t.plan(expectedTraces.length * 2)
+
+  var i = 0
+  var currentTrace = ''
+  var currentStack = ''
+
+  prettier.pipe(split(function (line) {
+    if (/^\s*"stack"/.test(line)) {
+      currentStack = line
+    }
+
+    if (/^\s*at/.test(line)) {
+      currentTrace = expectedTraces.shift()
+
+      t.ok(line.indexOf(currentTrace) >= 0, `${i} line matches`)
+      t.ok(getIndentLevel(line) > getIndentLevel(currentStack), `${i} proper indentation`)
+    }
+    i++
+    return line
+  }))
+
+  var instance = pino({ serializers: { err: serializers.err } }, prettier)
+
+  instance.info({ err })
+})
+
+test('pino transform prettifies Error in property within errorLikeObjectKeys when stack is not the last property', function (t) {
+  var prettier = pretty({
+    errorLikeObjectKeys: ['err']
+  })
+
+  var err = new Error('hello world')
+  err.anotherField = 'dummy value'
+
+  var expectedTraces = err.stack.split('\n').slice(1)
+
+  t.plan(expectedTraces.length * 2)
+
+  var i = 0
+  var currentTrace = ''
+  var currentStack = ''
+
+  prettier.pipe(split(function (line) {
+    if (/^\s*"stack"/.test(line)) {
+      currentStack = line
+    }
+
+    if (/^\s*at/.test(line)) {
+      currentTrace = expectedTraces.shift()
+
+      t.ok(line.indexOf(currentTrace) >= 0, `${i} line matches`)
+      t.ok(getIndentLevel(line) > getIndentLevel(currentStack), `${i} proper indentation`)
+    }
+    i++
+    return line
+  }))
+
+  var instance = pino({ serializers: { err: serializers.err } }, prettier)
+
+  instance.info({ err })
+})
+
 test('pino transform preserve output if not valid JSON', function (t) {
   t.plan(1)
   var prettier = pretty()