customProps causes TypeError: logger[stringifySym] is not a function

[jniemin]

customProps option is causing application to crash with

TypeError: logger[stringifySym] is not a function
  /Users/xxxx/node_modules/pino-http/logger.js:106
  const customPropBindingStr = logger[stringifySym](customPropBindings).replace(/[{}]/g, '')

After doing some debugging, seems that pino.child(bindings) call returns child logger which doesn't contain most of the symbols, including Symbol(pino.stringify).

You can see this by:

const logger = pino(pinoOptions);
console.log({logger})
const child = logger.child({});
console.log({child})

Internally pino-http does create child logger and stringify symbol is expected to be included later in the logger (https://github.com/pinojs/pino-http/blob/master/logger.js#L106)

 if (customPropBindings) {
      const customPropBindingStr = logger[stringifySym](customPropBindings).replace(/[{}]/g, '')
      const customPropBindingsStr = logger[chindingsSym]
      if (!customPropBindingsStr.includes(customPropBindingStr)) {
        log = logger.child(customPropBindings)
      }
    }

I was testing with pino 8.16.2 and pino-http 8.5.1

[alexkorsun]

Seems to be solved in 8.6.0

[AndrejSuperDebugger]

This is not resolved in version 8.6.0

[AndrejSuperDebugger]

#293

[alexkorsun]

I'm using pino with nestjs. Upgrade to 8.6.0 solved the issue on my end. 🤷‍♂️

[AndrejSuperDebugger]

I too am using pino with nestjs and updating to 8.6.0 did not solve the problem

[mcollina]

Thanks for reporting!

Can you provide steps to reproduce? We often need a reproducible example, e.g. some code that allows someone else to recreate your problem by just copying and pasting it. If it involves more than a couple of different file, create a new repository on GitHub and add a link to that.

[nuzayets]

Can confirm this occurs with latest pino/pino-http. Using Express, passing an existent root logger (not child) to pino-http. The pino child() function only sets stringifySym if redact is set in options and it's not copied in Object.create(this) because it's not part of the prototype. So, when pino-http forces a child with no options, we get a logger without stringifySym. This bug in pino-http was introduced in this PR: #288. I recommend reverting this commit. Currently using pino-http v8.3.3 as a workaround which is a pain because I'd really like to take the TypeScript changes in #295.

edit: It seems to occur when the base logger is instantiated in a separate package.

[nuzayets]

Right, of course. Here: https://github.com/pinojs/pino/blob/master/lib/symbols.js

stringifySym and chindingsSym as used by #288 are not created with Symbol.for in pino. So, if you are in a monorepo with the logger instantiated in a different package (even with the same version of pino), there is no global runtime search for the symbol values. Therefore they evaluate to different Symbols that are not equivalent, so the stringify function is inaccessible.

Here is a repro.

TEMPDIR=$(mktemp -d)
cd $TEMPDIR
mkdir logger
mkdir server

cat <<EOF > logger/package.json
{
  "name": "logger",
  "version": "1.0.0",
  "description": "",
  "main": "index.js",
  "type": "module",
  "author": "",
  "dependencies": {
    "pino": "^8.17.2"
  }
}
EOF

cat <<EOF > server/package.json
{
  "name": "server",
  "version": "1.0.0",
  "description": "",
  "main": "index.js",
  "type": "module",
  "author": "",
  "scripts": { "go": "node index.js" },
  "dependencies": {
    "express": "^4.18.2",
    "pino-http": "^9.0.0"
  }
}
EOF


cat <<EOF > logger/index.js
import pino from 'pino'
class Logger {
	constructor() {
		this.logger = pino({})
	}
	pino = () => this.logger
}
const logger = new Logger()
export default logger
EOF

cat <<EOF > server/index.js
import logger from 'logger'
import pinohttp from 'pino-http'
import http from 'http'
import express from 'express'

const app = express()
app.use(pinohttp({logger: logger.pino(), customProps: (req, res) => ({ ip: req.ip })}))
app.get('/', (req, res) => {
  res.send('Hello World!')
})
app.listen(31337, '127.0.0.1', () => {
	const req = http.request({port: 31337, host: '127.0.0.1'})
	req.end()
}).close()
EOF

cd logger
npm install
cd ../server
npm install -S ../logger
npm run go || true
rm -rf $TEMPDIR

[mcollina]

stringifySym and chindingsSym as used by #288 are not created with Symbol.for in pino.

Yes, this is on purpose.

So, if you are in a monorepo with the logger instantiated in a different package (even with the same version of pino)

Essentially, you are flagging a bug in your monorepo software ;).

[mcollina]

I think the solution to this bug is to support an optional parameter that allows a user to override the version of pino that it needs to be using.

Alternatively, we could expose pino.symbols as logger.symbols in pino itself.

[nuzayets]

Yes, this is on purpose.

Right. We're in the pino-http repo here. The bug is in #288 using these symbols to reference props set in another realm, not in pino for choosing to export unique symbols. If pino-http used these imported symbols to set props and then access them, all would be fine. Instead it is accessing props with a Symbol that it has no guarantee exists on the obj. pino-http is a separate package that interacts with pino through exports ...

I think the solution to this bug is to support an optional parameter that allows a user to override the version of pino that it needs to be using.

If you take a detailed look at the repro, there is only one version of pino. We're in the same runtime. It's not like we're instantiating pino in another instance of node and expecting to somehow RPC over to it. We're in the same process, same address space, same bits on disk. How do you even see that ('choosing which pino') working? We only import one.

[saisantosh]

@nuzayets I am facing the same issue. Were you able to figure out a workaround ?

[nuzayets]

@nuzayets I am facing the same issue. Were you able to figure out a workaround ?

Pinned an older version without the broken PR.

[AndrejSuperDebugger]

I solved my problem this way, I had the dependencies updated incorrectly. I once again, carefully and manually added the dependencies I needed and watched the yarn lock changes - the problem was solved

[fuadsaud]

I had been using [email protected] and [email protected] for a while without any issues and started experiencing this after bumping to [email protected]. I'm not entirely sure I understand why the previous combination of versions worked (since the proposed solution here is to pin pino-http on an older version). I'm resorting to pinning pino to the old version for now.

[david-szabo97]

We have the same issue with [email protected] and [email protected]

[mcollina]

the problem with pino@9 and pino-http@10 is out and it should work better.

The solution for this really is to remove the use of the private symbol:

pino-http/logger.js

Line 106 in bccda3c

const customPropBindingStr = logger[stringifySym](customPropBindings).replace(/[{}]/g, '')

.

[uorhsohk]

We are also facing the same issue using the latest version of pino:9.4.0 and pino-http:10.3.0.
We had to revert to 9.2.0 and 10.2.0 so that our application works again.

[quanth98]

I have same issue with pino:9.2.0 and pino-http:10.2.0 when build and run on docker from node:18.19.1-alpine