Excessively verbose req serializer?

[jsumners]

Consider this example app:

'use strict'

const app = require('express')()
const pino = require('pino')
const noir = require('pino-noir')(['req.headers.host'])
const serializers = {
  err: pino.stdSerializers.err
}
const logger = require('express-pino-logger')({
  level: 'debug',
  serializers: Object.assign({}, serializers, noir)
})

app.use(logger)

app.get('/', (req, reply) => {
  req.log.error(Error('this is a test'))
  reply.send('hello world')
})

app.listen(3000)

Issuing a simple GET to the endpoint results in a tremendous amount of logged data for the req object:

expand for output log

[2017-11-21T14:21:02.499Z] ERROR (1370 on dalekprime.local): this is a test
    Error: this is a test
        at app.get (/private/tmp/21/foo/index.js:17:17)
        at Layer.handle [as handle_request] (/private/tmp/21/foo/node_modules/express/lib/router/layer.js:95:5)
        at next (/private/tmp/21/foo/node_modules/express/lib/router/route.js:137:13)
        at Route.dispatch (/private/tmp/21/foo/node_modules/express/lib/router/route.js:112:3)
        at Layer.handle [as handle_request] (/private/tmp/21/foo/node_modules/express/lib/router/layer.js:95:5)
        at /private/tmp/21/foo/node_modules/express/lib/router/index.js:281:22
        at Function.process_params (/private/tmp/21/foo/node_modules/express/lib/router/index.js:335:12)
        at next (/private/tmp/21/foo/node_modules/express/lib/router/index.js:275:10)
        at loggingMiddleware (/private/tmp/21/foo/node_modules/pino-http/logger.js:62:7)
        at Layer.handle [as handle_request] (/private/tmp/21/foo/node_modules/express/lib/router/layer.js:95:5)
[2017-11-21T14:21:02.506Z] INFO (1370 on dalekprime.local): request completed
    req: {
      "_readableState": {
        "objectMode": false,
        "highWaterMark": 16384,
        "buffer": {
          "head": null,
          "tail": null,
          "length": 0
        },
        "length": 0,
        "pipes": null,
        "pipesCount": 0,
        "flowing": null,
        "ended": false,
        "endEmitted": false,
        "reading": false,
        "sync": true,
        "needReadable": false,
        "emittedReadable": false,
        "readableListening": false,
        "resumeScheduled": false,
        "destroyed": false,
        "defaultEncoding": "utf8",
        "awaitDrain": 0,
        "readingMore": true,
        "decoder": null,
        "encoding": null
      },
      "readable": true,
      "domain": null,
      "_events": {},
      "_eventsCount": 0,
      "socket": {
        "connecting": false,
        "_hadError": false,
        "_handle": {
          "reading": true,
          "owner": "[Circular]",
          "onconnection": null,
          "writeQueueSize": 0,
          "_consumed": true
        },
        "_parent": null,
        "_host": null,
        "_readableState": {
          "objectMode": false,
          "highWaterMark": 16384,
          "buffer": {
            "head": null,
            "tail": null,
            "length": 0
          },
          "length": 0,
          "pipes": null,
          "pipesCount": 0,
          "flowing": true,
          "ended": false,
          "endEmitted": false,
          "reading": true,
          "sync": false,
          "needReadable": true,
          "emittedReadable": false,
          "readableListening": false,
          "resumeScheduled": false,
          "destroyed": false,
          "defaultEncoding": "utf8",
          "awaitDrain": 0,
          "readingMore": false,
          "decoder": null,
          "encoding": null
        },
        "readable": true,
        "domain": null,
        "_events": {
          "end": [
            null,
            null
          ],
          "drain": [
            null,
            null
          ],
          "close": [
            null,
            null
          ]
        },
        "_eventsCount": 10,
        "_writableState": {
          "objectMode": false,
          "highWaterMark": 16384,
          "finalCalled": false,
          "needDrain": false,
          "ending": false,
          "ended": false,
          "finished": false,
          "destroyed": false,
          "decodeStrings": false,
          "defaultEncoding": "utf8",
          "length": 0,
          "writing": false,
          "corked": 0,
          "sync": true,
          "bufferProcessing": false,
          "writecb": null,
          "writelen": 0,
          "bufferedRequest": null,
          "lastBufferedRequest": null,
          "pendingcb": 0,
          "prefinished": false,
          "errorEmitted": false,
          "bufferedRequestCount": 0,
          "corkedRequestsFree": {
            "next": null,
            "entry": null
          }
        },
        "writable": true,
        "allowHalfOpen": true,
        "_bytesDispatched": 0,
        "_sockname": null,
        "_pendingData": null,
        "_pendingEncoding": "",
        "server": {
          "domain": null,
          "_events": {},
          "_eventsCount": 2,
          "_connections": 1,
          "_handle": {
            "reading": false,
            "owner": "[Circular]",
            "onread": null,
            "writeQueueSize": 0
          },
          "_usingSlaves": false,
          "_slaves": [],
          "_unref": false,
          "allowHalfOpen": true,
          "pauseOnConnect": false,
          "httpAllowHalfOpen": false,
          "timeout": 120000,
          "keepAliveTimeout": 5000,
          "_pendingResponseData": 0,
          "maxHeadersCount": null,
          "_connectionKey": "6::::3000"
        },
        "_server": {
          "domain": null,
          "_events": {},
          "_eventsCount": 2,
          "_connections": 1,
          "_handle": {
            "reading": false,
            "owner": "[Circular]",
            "onread": null,
            "writeQueueSize": 0
          },
          "_usingSlaves": false,
          "_slaves": [],
          "_unref": false,
          "allowHalfOpen": true,
          "pauseOnConnect": false,
          "httpAllowHalfOpen": false,
          "timeout": 120000,
          "keepAliveTimeout": 5000,
          "_pendingResponseData": 0,
          "maxHeadersCount": null,
          "_connectionKey": "6::::3000"
        },
        "_idleTimeout": 120000,
        "_idleNext": {
          "_idleNext": "[Circular]",
          "_idlePrev": "[Circular]",
          "_timer": {
            "_list": "[Circular]"
          },
          "_unrefed": true,
          "msecs": 120000,
          "nextTick": false
        },
        "_idlePrev": {
          "_idleNext": "[Circular]",
          "_idlePrev": "[Circular]",
          "_timer": {
            "_list": "[Circular]"
          },
          "_unrefed": true,
          "msecs": 120000,
          "nextTick": false
        },
        "_idleStart": 7229,
        "_destroyed": false,
        "parser": {
          "_headers": [],
          "_url": "",
          "_consumed": true,
          "socket": "[Circular]",
          "incoming": "[Circular]",
          "outgoing": null,
          "maxHeaderPairs": 2000
        },
        "_paused": false,
        "_consuming": true,
        "_httpMessage": {
          "domain": null,
          "_events": {},
          "_eventsCount": 1,
          "output": [],
          "outputEncodings": [],
          "outputCallbacks": [],
          "outputSize": 0,
          "writable": true,
          "_last": false,
          "upgrading": false,
          "chunkedEncoding": false,
          "shouldKeepAlive": true,
          "useChunkedEncodingByDefault": true,
          "sendDate": true,
          "_removedConnection": false,
          "_removedContLen": false,
          "_removedTE": false,
          "_contentLength": null,
          "_hasBody": true,
          "_trailer": "",
          "finished": false,
          "_headerSent": false,
          "socket": "[Circular]",
          "connection": "[Circular]",
          "_header": null,
          "_sent100": false,
          "_expect_continue": false,
          "req": "[Circular]",
          "locals": {}
        }
      },
      "connection": {
        "connecting": false,
        "_hadError": false,
        "_handle": {
          "reading": true,
          "owner": "[Circular]",
          "onconnection": null,
          "writeQueueSize": 0,
          "_consumed": true
        },
        "_parent": null,
        "_host": null,
        "_readableState": {
          "objectMode": false,
          "highWaterMark": 16384,
          "buffer": {
            "head": null,
            "tail": null,
            "length": 0
          },
          "length": 0,
          "pipes": null,
          "pipesCount": 0,
          "flowing": true,
          "ended": false,
          "endEmitted": false,
          "reading": true,
          "sync": false,
          "needReadable": true,
          "emittedReadable": false,
          "readableListening": false,
          "resumeScheduled": false,
          "destroyed": false,
          "defaultEncoding": "utf8",
          "awaitDrain": 0,
          "readingMore": false,
          "decoder": null,
          "encoding": null
        },
        "readable": true,
        "domain": null,
        "_events": {
          "end": [
            null,
            null
          ],
          "drain": [
            null,
            null
          ],
          "close": [
            null,
            null
          ]
        },
        "_eventsCount": 10,
        "_writableState": {
          "objectMode": false,
          "highWaterMark": 16384,
          "finalCalled": false,
          "needDrain": false,
          "ending": false,
          "ended": false,
          "finished": false,
          "destroyed": false,
          "decodeStrings": false,
          "defaultEncoding": "utf8",
          "length": 0,
          "writing": false,
          "corked": 0,
          "sync": true,
          "bufferProcessing": false,
          "writecb": null,
          "writelen": 0,
          "bufferedRequest": null,
          "lastBufferedRequest": null,
          "pendingcb": 0,
          "prefinished": false,
          "errorEmitted": false,
          "bufferedRequestCount": 0,
          "corkedRequestsFree": {
            "next": null,
            "entry": null
          }
        },
        "writable": true,
        "allowHalfOpen": true,
        "_bytesDispatched": 0,
        "_sockname": null,
        "_pendingData": null,
        "_pendingEncoding": "",
        "server": {
          "domain": null,
          "_events": {},
          "_eventsCount": 2,
          "_connections": 1,
          "_handle": {
            "reading": false,
            "owner": "[Circular]",
            "onread": null,
            "writeQueueSize": 0
          },
          "_usingSlaves": false,
          "_slaves": [],
          "_unref": false,
          "allowHalfOpen": true,
          "pauseOnConnect": false,
          "httpAllowHalfOpen": false,
          "timeout": 120000,
          "keepAliveTimeout": 5000,
          "_pendingResponseData": 0,
          "maxHeadersCount": null,
          "_connectionKey": "6::::3000"
        },
        "_server": {
          "domain": null,
          "_events": {},
          "_eventsCount": 2,
          "_connections": 1,
          "_handle": {
            "reading": false,
            "owner": "[Circular]",
            "onread": null,
            "writeQueueSize": 0
          },
          "_usingSlaves": false,
          "_slaves": [],
          "_unref": false,
          "allowHalfOpen": true,
          "pauseOnConnect": false,
          "httpAllowHalfOpen": false,
          "timeout": 120000,
          "keepAliveTimeout": 5000,
          "_pendingResponseData": 0,
          "maxHeadersCount": null,
          "_connectionKey": "6::::3000"
        },
        "_idleTimeout": 120000,
        "_idleNext": {
          "_idleNext": "[Circular]",
          "_idlePrev": "[Circular]",
          "_timer": {
            "_list": "[Circular]"
          },
          "_unrefed": true,
          "msecs": 120000,
          "nextTick": false
        },
        "_idlePrev": {
          "_idleNext": "[Circular]",
          "_idlePrev": "[Circular]",
          "_timer": {
            "_list": "[Circular]"
          },
          "_unrefed": true,
          "msecs": 120000,
          "nextTick": false
        },
        "_idleStart": 7229,
        "_destroyed": false,
        "parser": {
          "_headers": [],
          "_url": "",
          "_consumed": true,
          "socket": "[Circular]",
          "incoming": "[Circular]",
          "outgoing": null,
          "maxHeaderPairs": 2000
        },
        "_paused": false,
        "_consuming": true,
        "_httpMessage": {
          "domain": null,
          "_events": {},
          "_eventsCount": 1,
          "output": [],
          "outputEncodings": [],
          "outputCallbacks": [],
          "outputSize": 0,
          "writable": true,
          "_last": false,
          "upgrading": false,
          "chunkedEncoding": false,
          "shouldKeepAlive": true,
          "useChunkedEncodingByDefault": true,
          "sendDate": true,
          "_removedConnection": false,
          "_removedContLen": false,
          "_removedTE": false,
          "_contentLength": null,
          "_hasBody": true,
          "_trailer": "",
          "finished": false,
          "_headerSent": false,
          "socket": "[Circular]",
          "connection": "[Circular]",
          "_header": null,
          "_sent100": false,
          "_expect_continue": false,
          "req": "[Circular]",
          "locals": {}
        }
      },
      "httpVersionMajor": 1,
      "httpVersionMinor": 1,
      "httpVersion": "1.1",
      "complete": false,
      "headers": {
        "host": "[Redacted]",
        "user-agent": "curl/7.56.1",
        "accept": "*/*"
      },
      "rawHeaders": [
        "Host",
        "localhost:3000",
        "User-Agent",
        "curl/7.56.1",
        "Accept",
        "*/*"
      ],
      "trailers": {},
      "rawTrailers": [],
      "upgrade": false,
      "url": "/",
      "method": "GET",
      "statusCode": null,
      "statusMessage": null,
      "client": {
        "connecting": false,
        "_hadError": false,
        "_handle": {
          "reading": true,
          "owner": "[Circular]",
          "onconnection": null,
          "writeQueueSize": 0,
          "_consumed": true
        },
        "_parent": null,
        "_host": null,
        "_readableState": {
          "objectMode": false,
          "highWaterMark": 16384,
          "buffer": {
            "head": null,
            "tail": null,
            "length": 0
          },
          "length": 0,
          "pipes": null,
          "pipesCount": 0,
          "flowing": true,
          "ended": false,
          "endEmitted": false,
          "reading": true,
          "sync": false,
          "needReadable": true,
          "emittedReadable": false,
          "readableListening": false,
          "resumeScheduled": false,
          "destroyed": false,
          "defaultEncoding": "utf8",
          "awaitDrain": 0,
          "readingMore": false,
          "decoder": null,
          "encoding": null
        },
        "readable": true,
        "domain": null,
        "_events": {
          "end": [
            null,
            null
          ],
          "drain": [
            null,
            null
          ],
          "close": [
            null,
            null
          ]
        },
        "_eventsCount": 10,
        "_writableState": {
          "objectMode": false,
          "highWaterMark": 16384,
          "finalCalled": false,
          "needDrain": false,
          "ending": false,
          "ended": false,
          "finished": false,
          "destroyed": false,
          "decodeStrings": false,
          "defaultEncoding": "utf8",
          "length": 0,
          "writing": false,
          "corked": 0,
          "sync": true,
          "bufferProcessing": false,
          "writecb": null,
          "writelen": 0,
          "bufferedRequest": null,
          "lastBufferedRequest": null,
          "pendingcb": 0,
          "prefinished": false,
          "errorEmitted": false,
          "bufferedRequestCount": 0,
          "corkedRequestsFree": {
            "next": null,
            "entry": null
          }
        },
        "writable": true,
        "allowHalfOpen": true,
        "_bytesDispatched": 0,
        "_sockname": null,
        "_pendingData": null,
        "_pendingEncoding": "",
        "server": {
          "domain": null,
          "_events": {},
          "_eventsCount": 2,
          "_connections": 1,
          "_handle": {
            "reading": false,
            "owner": "[Circular]",
            "onread": null,
            "writeQueueSize": 0
          },
          "_usingSlaves": false,
          "_slaves": [],
          "_unref": false,
          "allowHalfOpen": true,
          "pauseOnConnect": false,
          "httpAllowHalfOpen": false,
          "timeout": 120000,
          "keepAliveTimeout": 5000,
          "_pendingResponseData": 0,
          "maxHeadersCount": null,
          "_connectionKey": "6::::3000"
        },
        "_server": {
          "domain": null,
          "_events": {},
          "_eventsCount": 2,
          "_connections": 1,
          "_handle": {
            "reading": false,
            "owner": "[Circular]",
            "onread": null,
            "writeQueueSize": 0
          },
          "_usingSlaves": false,
          "_slaves": [],
          "_unref": false,
          "allowHalfOpen": true,
          "pauseOnConnect": false,
          "httpAllowHalfOpen": false,
          "timeout": 120000,
          "keepAliveTimeout": 5000,
          "_pendingResponseData": 0,
          "maxHeadersCount": null,
          "_connectionKey": "6::::3000"
        },
        "_idleTimeout": 120000,
        "_idleNext": {
          "_idleNext": "[Circular]",
          "_idlePrev": "[Circular]",
          "_timer": {
            "_list": "[Circular]"
          },
          "_unrefed": true,
          "msecs": 120000,
          "nextTick": false
        },
        "_idlePrev": {
          "_idleNext": "[Circular]",
          "_idlePrev": "[Circular]",
          "_timer": {
            "_list": "[Circular]"
          },
          "_unrefed": true,
          "msecs": 120000,
          "nextTick": false
        },
        "_idleStart": 7229,
        "_destroyed": false,
        "parser": {
          "_headers": [],
          "_url": "",
          "_consumed": true,
          "socket": "[Circular]",
          "incoming": "[Circular]",
          "outgoing": null,
          "maxHeaderPairs": 2000
        },
        "_paused": false,
        "_consuming": true,
        "_httpMessage": {
          "domain": null,
          "_events": {},
          "_eventsCount": 1,
          "output": [],
          "outputEncodings": [],
          "outputCallbacks": [],
          "outputSize": 0,
          "writable": true,
          "_last": false,
          "upgrading": false,
          "chunkedEncoding": false,
          "shouldKeepAlive": true,
          "useChunkedEncodingByDefault": true,
          "sendDate": true,
          "_removedConnection": false,
          "_removedContLen": false,
          "_removedTE": false,
          "_contentLength": null,
          "_hasBody": true,
          "_trailer": "",
          "finished": false,
          "_headerSent": false,
          "socket": "[Circular]",
          "connection": "[Circular]",
          "_header": null,
          "_sent100": false,
          "_expect_continue": false,
          "req": "[Circular]",
          "locals": {}
        }
      },
      "_consuming": false,
      "_dumped": false,
      "baseUrl": "",
      "originalUrl": "/",
      "_parsedUrl": {
        "protocol": null,
        "slashes": null,
        "auth": null,
        "host": null,
        "port": null,
        "hostname": null,
        "hash": null,
        "search": null,
        "query": null,
        "pathname": "/",
        "path": "/",
        "href": "/",
        "_raw": "/"
      },
      "params": {},
      "query": {},
      "res": {
        "domain": null,
        "_events": {},
        "_eventsCount": 1,
        "output": [],
        "outputEncodings": [],
        "outputCallbacks": [],
        "outputSize": 0,
        "writable": true,
        "_last": false,
        "upgrading": false,
        "chunkedEncoding": false,
        "shouldKeepAlive": true,
        "useChunkedEncodingByDefault": true,
        "sendDate": true,
        "_removedConnection": false,
        "_removedContLen": false,
        "_removedTE": false,
        "_contentLength": null,
        "_hasBody": true,
        "_trailer": "",
        "finished": false,
        "_headerSent": false,
        "socket": "[Circular]",
        "connection": "[Circular]",
        "_header": null,
        "_sent100": false,
        "_expect_continue": false,
        "req": "[Circular]",
        "locals": {}
      },
      "id": 1
    }
    res: {
      "statusCode": 200,
      "header": "HTTP/1.1 200 OK\r\nX-Powered-By: Express\r\nContent-Type: text/html; charset=utf-8\r\nContent-Length: 11\r\nETag: W/\"b-Kq5sNclPz7QV2+lfQIuc6R7oRu0\"\r\nDate: Tue, 21 Nov 2017 14:21:02 GMT\r\nConnection: keep-alive\r\n\r\n"
    }
    responseTime: 7

This does not seem right, particularly considering the example output in the documentation here. I'm not an express guy, is this normal? Also notice that this output makes redacting material doubly complicated (e.g. req.headers and req.rawHeaders).

[davidmarkclements]

something must have changed with the serializer in pino-http

this isn't right

[davidmarkclements]

wait what if you don't specify any serializers..

I know you need to for noir

I suspect what's happening here is the asReqValue isn't being applied because it's lost from the serializers

think we need do a slight API change

1. on the serializers options, check for req/res keys
2. if they don't exist, apply the internal req/res
3. if they do, override - UNLESS they are set to null, in which case don't apply

[jsumners]

@davidmarkclements are you working on this?

[davidmarkclements]

not currently - feel free

the parallel work in hapijs/hapi-pino#34 looks to be a helpful reference point

we need to do this in pino-http instead, so this issue should be moved

[jsumners]

I suppose the fix here will be updating the pino-http dependency to v3.0.0.

[mcollina]

yes!