pinojs / pino

🌲 super fast, all natural json logger
http://getpino.io
MIT License
14.27k stars 875 forks source link

`stdSerializers` cannot be avoided for Request and Response #1991

Open gerardolima opened 4 months ago

gerardolima commented 4 months ago

First of all, thank you for this great library!!

When any logger method (ie info) receives a Request, pino serializes the object using pino.stdSerializers.req and stores in req property; this value is, then, passed to the actual serializer function given by the options. This also happens to Response objects:

const opts = {
  serializers: { 
    'req': mySerializerReq,
    'res': mySerializerRes,
}
const logger = pino(opts)
logger.info(myReq) // serialized as `mySerializerReq(pino.stdSerializers.req(myReq))`
logger.info(myRes) // serialized as  `mySerializerRes(pino.stdSerializers.res(myRes))`

This is inefficient, performance-wise, and also can lead to unexpected behaviour, when the provided serializer requires some property from the object that is removed by pino.stdSerializers.*.

gerardolima commented 4 months ago

I tested using this script, below:

import {describe, it} from 'node:test'
import assert from 'node:assert/strict'
import pino from 'pino';

const makeWriter = () => {
  const acc = [];
  return {
    write: (chunk) => { acc.push(chunk); },
    entries: () => [...acc],
  };
};

describe('stdSerializers', () => {

  it('serializes `.mySpecialProperty` for Errors', () => {
    // this test is OK

    // `err` property is resolved at `pino/lib/proto.js:write`
    // see https://github.com/pinojs/pino/blob/8db130eba0439e61c802448d31eb1998cebfbc98/lib/proto.js#L191

    const myErr = new Error()
    myErr.mySpecialProperty = Math.random()

    const writer = makeWriter()
    const opts = { serializers: { 'err': obj => ({ mySpecialProperty: obj.mySpecialProperty }) } }
    const logger = pino(opts, writer)

    logger.info(myErr)

    const entries = writer.entries()
    assert.equal(entries.length, 1)

    const obj = JSON.parse(entries[0])
    assert.deepEqual(obj.err, {mySpecialProperty: myErr.mySpecialProperty})
  })

  it('serializes `.mySpecialProperty` for Requests', () => {
    // this test fails

    // error property is resolved at `pino/lib/tools.js:genLog:LOG` -> `pino-std-serializers/index.d.ts:mapHttpRequest`
    // see https://github.com/pinojs/pino/blob/8db130eba0439e61c802448d31eb1998cebfbc98/lib/tools.js#L44
    // see https://github.com/pinojs/pino-std-serializers/blob/dc2ce14ebb9497d2ebe1a37c9f0da8d711ef5cc0/index.d.ts#L89

    const myReq = {
      method: 'any-fake-method',
      headers: 'any-fake-headers',
      socket: 'any-fake-socket',
    }
    myReq.mySpecialProperty = Math.random()

    const writer = makeWriter()
    const opts = { serializers: { 'req': obj => ({ mySpecialProperty: obj.mySpecialProperty }) } }
    const logger = pino(opts, writer)

    logger.info(myReq)

    const entries = writer.entries()
    assert.equal(entries.length, 1)

    const obj = JSON.parse(entries[0])
    assert.deepEqual(obj.req, {mySpecialProperty: myReq.mySpecialProperty})
  })

  it('serializes `.mySpecialProperty` for Responses', () => {
    // this test fails

    // error property is resolved at `pino/lib/tools.js:genLog:LOG` -> `pino-std-serializers/index.d.ts:mapHttpResponse`
    // see https://github.com/pinojs/pino/blob/8db130eba0439e61c802448d31eb1998cebfbc98/lib/tools.js#L46
    // see  https://github.com/pinojs/pino-std-serializers/blob/dc2ce14ebb9497d2ebe1a37c9f0da8d711ef5cc0/index.d.ts#L116

    const myRes = {
      setHeader: () => undefined,
    }
    myRes.mySpecialProperty = Math.random()

    const writer = makeWriter()
    const opts = { serializers: { 'res': obj => ({ mySpecialProperty: obj.mySpecialProperty }) } }
    const logger = pino(opts, writer)

    logger.info(myRes, 'any-message')

    const entries = writer.entries()
    assert.equal(entries.length, 1)

    const obj = JSON.parse(entries[0])
    assert.deepEqual(obj.res, {mySpecialProperty: myRes.mySpecialProperty})
  })
})
mcollina commented 3 months ago

I think we should deprecate this behavior in this release, and remove in the next one. Would you like to send a PR?

gerardolima commented 3 months ago

I think we should deprecate this behavior in this release, and remove in the next one. Would you like to send a PR?

I would like it very much to contribute, but right now I'm overwhelmed. Do you already have a date for the next release?

mcollina commented 3 months ago

They happen when they happen