Should include cookie field as well if present in pino req object

[MDAkramSiddiqui]

I am using cookie-parser to parse the cookie from headers to object that becomes available as cookie field on req object.

While using pino serializers for logging, I am not getting those parsed cookies in pino req object.

[mcollina]

If you want to have these information, you can add your own serializer for req.

[MDAkramSiddiqui]

I passed my own serializer in pinoHttp middleware options like below, but still not able to get cookies in req object being passed as an argument in the req function of the serializer.

On checking saw that this req argument is being passed via this function https://github.com/pinojs/pino-std-serializers/blob/1a136f6549fb09d1820b2d30f21cd765a95a6aba/index.js#L26

Reference in pino-http repo from where this is being called https://github.com/pinojs/pino-http/blob/master/logger.js#L33

That is why added the change here, if there is any other approach than your guidance would be appreciated. Thanks!

    serializers: {
        req: (req: Request) => {
                  ^^^--  it does not have cookies object

            return {
                id: req.id,
                method: req.method,
                url: req.url,
                deviceId: req.cookies.deviceId,
            };
        },
        res: (res: Response) => ({
            statusCode: res.statusCode,
        })

[mcollina]

can you please include a full reproduction? That should be there?

[MDAkramSiddiqui]

@jsumners in context of - https://github.com/pinojs/pino-std-serializers/pull/156#pullrequestreview-2420664166

This is not a good idea. Cookies typically contain sensitive information. The purpose of these standard serializers is to log basic information that can be stored in a long term log store. We cannot log cookies by default.

• by default enable autoLogging is true and there we are logging headers and thus cookies are already being logged

[MDAkramSiddiqui]

@jsumners in context of - https://github.com/pinojs/pino-std-serializers/pull/156#pullrequestreview-2420664166

I recommend writing your own request serializer, or using https://github.com/pinojs/pino-std-serializers#exportswraprequestserializercustomserializer

I am using pino-http library which internally uses pino-std-serializers and on line 33, it is using request wrapper function serializers.wrapRequestSerializer exported via pino-std-serializers. https://github.com/pinojs/pino-http/blob/master/logger.js#L33

And this wrapRequestSerializer, wraps and passes the req argument to the custom serializer function passed as argument during pino-http initalization. https://github.com/pinojs/pino-std-serializers/blob/master/index.js#L23C1-L28C5

Seems like we cannot add custom logic for this unless we add support for that as well in pino-http library.

Reproduction link - https://replit.com/@MDAkramSiddiqui/Testing81125

[MDAkramSiddiqui]

Incase above reproduction link do not work - https://codesandbox.io/p/devbox/p9s9h2

[MDAkramSiddiqui]

@mcollina @jsumners bump ^^

[jsumners]

@jsumners in context of - #156 (review)

This is not a good idea. Cookies typically contain sensitive information. The purpose of these standard serializers is to log basic information that can be stored in a long term log store. We cannot log cookies by default.

• by default enable autoLogging is true and there we are logging headers and thus cookies are already being logged

I don't know what this means. What is "autoLogging"?

@jsumners in context of - #156 (review)

I recommend writing your own request serializer, or using pinojs/pino-std-serializers#exportswraprequestserializercustomserializer

I am using pino-http library which internally uses pino-std-serializers and on line 33, it is using request wrapper function serializers.wrapRequestSerializer exported via pino-std-serializers. pinojs/pino-http@master/logger.js#L33

And this wrapRequestSerializer, wraps and passes the req argument to the custom serializer function passed as argument during pino-http initalization. master/index.js#L23C1-L28C5

Seems like we cannot add custom logic for this unless we add support for that as well in pino-http library.

Reproduction link - replit.com/@MDAkramSiddiqui/Testing81125

https://github.com/pinojs/pino-http#logger-options clearly shows that you can supply your own serializer.

[MDAkramSiddiqui]

I don't know what this means. What is "autoLogging"?

autoLogging: set to false, to disable the automatic "request completed" and "request errored" logging. Defaults to true. If set to an object, you can provide more options. https://github.com/pinojs/pino-http

https://github.com/pinojs/pino-http#logger-options clearly shows that you can supply your own serializer.

Yes, I am passing my own serializer as mentioned in the doc, but still cannot access cookies because there is another wrapper function over the the request object that is being passed as param to the serializer function

And this wrapRequestSerializer, wraps and passes the req argument to the custom serializer function passed as argument during pino-http initalization. master/index.js#L23C1-L28C5

Please refer LoggerMiddleware.js file, in this reproduction setup - https://github.com/pinojs/pino-std-serializers/issues/155#issuecomment-2463984577

[jsumners]

'use strict'

const http = require('node:http')
const serializers = require('pino-std-serializers')
const logger = require('pino-http')({
  serializers: {
    req: serializers.req,
    res: serializers.res
  }
})

const server = http.createServer(handler)
server.listen(0)

http.get(`http://localhost:${server.address().port}/`, {
  headers: {
    cookie: 'my-cookie=foobar'
  }
}).end()

function handler (req, res) {
  logger(req, res)
  req.log.info('servicing request')
  res.end('ok')
}

When I run that script I get:

{"level":30,"time":1731497119903,"pid":3544,"hostname":"redacted","req":{"id":1,"method":"GET","url":"/","headers":{"cookie":"my-cookie=foobar","host":"localhost:62294","connection":"keep-alive"},"remoteAddress":"::1","remotePort":62295},"msg":"servicing request"}
{"level":30,"time":1731497119907,"pid":3544,"hostname":"redacted","req":{"id":1,"method":"GET","url":"/","headers":{"cookie":"my-cookie=foobar","host":"localhost:62294","connection":"keep-alive"},"remoteAddress":"::1","remotePort":62295},"res":{"statusCode":200,"headers":{}},"responseTime":5,"msg":"request completed"}

We can see, the supplied cookie my-cookie=foobar is included in both the serialized request and serialized response.

If we adjust the script to:

'use strict'

const http = require('node:http')
const serializers = require('pino-std-serializers')
const logger = require('pino-http')({
  serializers: {
    req: serializers.wrapRequestSerializer(reqSerializer),
    res: serializers.res
  }
})

const server = http.createServer(handler)
server.listen(0)

http.get(`http://localhost:${server.address().port}/`, {
  headers: {
    cookie: 'my-cookie=foobar'
  }
}).end()

function handler (req, res) {
  logger(req, res)
  req.log.info('servicing request')
  res.end('ok')
}

function reqSerializer (req) {
  return { cookies: req.headers.cookie }
}

Then we get:

{"level":30,"time":1731497384530,"pid":3792,"hostname":"redacted","req":{"cookies":"my-cookie=foobar"},"msg":"servicing request"}
{"level":30,"time":1731497384531,"pid":3792,"hostname":"redacted","req":{"cookies":"my-cookie=foobar"},"res":{"statusCode":200,"headers":{}},"responseTime":1,"msg":"request completed"}

So I am unclear what issue is being described. In fact, in my opinion, the real issue is that the cookie header is included at all.

[MDAkramSiddiqui]

When I run that script I get: {"level":30,"time":1731497119903,"pid":3544,"hostname":"redacted","req":{"id":1,"method":"GET","url":"/","headers":{"cookie":"my-cookie=foobar","host":"localhost:62294","connection":"keep-alive"},"remoteAddress":"::1","remotePort":62295},"msg":"servicing request"} {"level":30,"time":1731497119907,"pid":3544,"hostname":"redacted","req":{"id":1,"method":"GET","url":"/","headers":{"cookie":"my-cookie=foobar","host":"localhost:62294","connection":"keep-alive"},"remoteAddress":"::1","remotePort":62295},"res":{"statusCode":200,"headers":{}},"responseTime":5,"msg":"request completed"}

This is what exactly autoLogging param by default does, it logs all headers.

We can see, the supplied cookie my-cookie=foobar is included in both the serialized request and serialized response.

Basically, what you are seeing is the cookie string, express' cookie-parser middleware parses this cookie header string to an object and add that to req object as cookies field.

I am also passing the serializer, as below -

  serializers: {
    req: (req) => {
      return {
        id: req.id,
        method: req.method,
        url: req.url,
        deviceId: req.cookies?.deviceId,
      };
    },
    res: (res) => ({
      statusCode: res.statusCode,
    }),
  },

its just that the parsed cookies object is not available. So it comes down to two options -

1. parse those manually again for each log, which is not ideal as it unnecessarily consumes computation resources (also will have to request this feature to expose this api from the cookie-parser middleware
2. request here to make this cookies field available on req object.

So I am unclear what issue is being described. In fact, in my opinion, the real issue is that the cookie header is included at all.

Yes, by default it should be redacted.

[jsumners]

@mcollina I think we both misunderstood the intent of #156. What it is doing is adding yet another framework specific compatibility like these:

https://github.com/pinojs/pino-std-serializers/blob/1a136f6549fb09d1820b2d30f21cd765a95a6aba/lib/req.js#L66-L67

https://github.com/pinojs/pino-std-serializers/blob/1a136f6549fb09d1820b2d30f21cd765a95a6aba/lib/req.js#L71-L74

I think what was missing from the original PR was comments explaining that (as illustrated above). Should we re-open and ask for that change?