pino-noir hangs the server (redacting req.headers)

[floridemai]

Tried to use pino-noir in the following way:

  opts.serializers = noir([
    'created',
    'req.headers.authorization'
  ], '[Redacted]')

Server hangs.
Note that the created property is redacted on the server start event and the bug seems to kick in when having to deal with the request headers.

[novemberborn]

Is this with Hapi? I've tried to redact req.headers.cookie which seems to modify the actual outgoing request object, crashing Hapi.

[mcollina]

Can you please provide an example to reproduce the issue?

[novemberborn]

@mcollina see https://github.com/novemberborn/_pino-noir-hapi-repro.

I think there the issues are unrelated. The example given for Hapi causes seemingly infinite log output (probably a circular recursion problem). Uncomment https://github.com/novemberborn/_pino-noir-hapi-repro/blob/b0a40659bb2e4a3046095690d88f9c30cfbda3a9/index.js#L42 to see.

Redacting cookies is tricky because asReqValue needs to be copied out of hapi-pino. But then if the cookie is present, it actually crashes Hapi. See: https://github.com/novemberborn/_pino-noir-hapi-repro/blob/b0a40659bb2e4a3046095690d88f9c30cfbda3a9/index.js#L46:L48

Clone the repo, run npm install, and then node index.js. It should start a server at http://localhost:8000/hello.

[davidmarkclements]

ok here's the problem (thanks @novemberborn for the example)

• the server.ext('onRequest') hook creates a child logger of the request object as ({req: request})
• the request object is passed to this.serializers which hits pino-noir,
• pino-noir runs the asReqValue serializer to get the req object (btw, we should be able to grab this from hapi-pino instead of rewriting it, if not hapi-pino should expose it I think)
• the req object is then processed for redactions, req.headers.cookie is converted to a Redacted placeholder instance - important to note here that Redacted objects retain a reference to the parent object - hence.. a circular reference
• the req object is then passed to this.stringify in pino - which is fast-safe-stringify - the point of fast-safe-stringify is to work around circular references (maybe we can see where this is going)
• pino-noir sets the forceDecirc flag on the toJSON function of the Redacted instance (Force decirc when toJSON with Symbol.for('forceDecirc') davidmarkclements/fast-safe-stringify#17) - this is to ensure that the original object (pre-redaction) is scoped out for circular references by fast-safe-stringify
• however, the unintended side effect is that this checks the parent property as a circular - and since at this moment req.headers.cookie.parent === req.headers it marks it as a circular reference, replacing the parent key with a Circular placeholder instance , and the val is set to the Redacted placeholder instance
• when the object is stringified, the toJSON of the Circular.prototype replaces the parent with the value (as usual) - however the because the value is now Redacted instance instead of the cookie string we've left the wrong value on the object
• later on Hapi tries to use the replace method on cookies (which is header.cookie) expecting it to be a string, and it isn't a string - server crashes.

This is going to be a tricky fix, but here's what I reckon is best for minimum impact

• add another flag , forceDecircOnSingleKey (better names welcome)
• check parent.toJSON.forceDecircOnSingleKey === k about... here https://github.com/davidmarkclements/fast-safe-stringify/blob/master/index.js#L32
• only perform circular check if k matches the key
• in pino-noir set Redacted.prototype.toJSON.forceDecircOnSingleKey = 'val'

@mcollina I'd welcome less ugly ideas - bear in mind I still want to keep fast-safe-stringify legacy compatible (including older browsers etc) so using Symbols is out

[kishoresanke]

@mcollina / @davidmarkclements , I'm facing the same exact issue on hapi.. what was the resolution for this ?

Versions i'm using :-

├─┬ hapi-pino@2.1.1
│ └─┬ pino@4.10.3
├── pino-noir@2.0.0