CPU Hang with infinite decirc

[SebastienElet]

Hello,

I experienced downtime from pino logger.
A developer accidentally logged an express req in pino, and on catch It made our api hang with full CPU.

Here a small exemple of the expressjs middleware used :

import { NextFunction, Request, Response } from 'express'
import pino from 'pino'

export const webhook = (
  req: Request,
  res: Response,
  next: NextFunction,
) => {
  const logger = pino({
    name: 'test',
    prettyPrint: {
      colorize: true,
      translateTime: true,
      messageFormat: '{hostname} - {pid} - {msg}',
      ignore: 'hostname,pid',
    },
  })

  logger.error({ req })
}

Node version : 12.9.0
Typescript : 4.1.3
Pino : 6.11.2
Pino-pretty : 4.7.1
Express : 4.17.1

Here is a profiler trace

[davidmarkclements]

Thanks for the trace. The repeating decirc indicates this is looping on a circular reference. I may be wrong here but I don’t think we handle these cases because the perf cost of doing so is too great. We use serialisers to address this problem, and pino-express (pino-http) has them built in for req objects.

…

On Wed, 24 Mar 2021 at 13:53, Sébastien ELET ***@***.***> wrote: Hello, I experienced downtime from pino logger. A developer accidentally logged an express req in pino, and on catch It made our api hang with full CPU. Here a small exemple of the expressjs middleware used : import { NextFunction, Request, Response } from 'express' import pino from 'pino' export const webhook = ( req: Request, res: Response, next: NextFunction, ) => { const logger = pino({ name: 'test', prettyPrint: { colorize: true, translateTime: true, messageFormat: '{hostname} - {pid} - {msg}', ignore: 'hostname,pid', }, }) logger.error({ req }) } Node version : 12.9.0 Typescript : 4.1.3 Pino : 6.11.2 Pino-pretty : 4.7.1 Express : 4.17.1 Here is a profiler trace [image: Capture d’écran 2021-03-24 à 13 51 32] <https://user-images.githubusercontent.com/541937/112313397-159df580-8ca8-11eb-858f-68d948e26c16.png> — You are receiving this because you are subscribed to this thread. Reply to this email directly, view it on GitHub <#990>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AAJCWPGOTKXSHVE6XDITERLTFHOE3ANCNFSM4ZXGLTFQ> .

[mcollina]

I thought decirc was supposed to detect the circular reference and do something about it. I thought our default behavior was throwing something.

[mcollina]

@davidmarkclements you wrote https://www.npmjs.com/package/fast-safe-stringify to support this use case.

[mcollina]

Here is decirc: https://github.com/davidmarkclements/fast-safe-stringify/blob/0e011f068962e8f8974133a47afcabfc003f2183/index.js#L28.

[SebastienElet]

Thanks for the feedback, I'm able to remove req with the following code :

  const logger = pino({
    name: 'test',
    serializers: {
      req: () => ({}),
    },
  })

  logger.info({ req })

However if any circular deps is injected my process hang :

  const logger = pino({
    name: 'test',
    serializers: {
      req: () => ({}),
    },
  })

  logger.info({ test: req })

I don't need to output req, I may trash it but I would like to keep my process alive 🙏
I would be happy to help I you need more information.

[davidmarkclements]

Hahaha oh right yeah. Seb can you provide more info about what’s on the req object

…

On Wed, 24 Mar 2021 at 15:06, Matteo Collina ***@***.***> wrote: Here is decirc: https://github.com/davidmarkclements/fast-safe-stringify/blob/0e011f068962e8f8974133a47afcabfc003f2183/index.js#L28 . — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub <#990 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AAJCWPFXYWKC7T63ECILUSTTFHWV7ANCNFSM4ZXGLTFQ> .

[mcollina]

can you provide an example to fully reproduce? I think this is covered by several of our unit tests.

[SebastienElet]

I tried to remove all custom stuff attached on req and it worked.

I just found the cause as I attach a PrismaClient (Postgresql ORM) on it

import { PrismaClient } from '@prisma/client'

const prisma = new PrismaClient()
app.use((req, res, next) => {
  req.prisma = prisma
  next()
})

I will try to produce a minimal example

[mcollina]

Thanks, that would be really helpful.

[SebastienElet]

I removed all the http layer and only the prisma client is involved.
I have a minimal example available here : https://gist.github.com/SebastienElet/8e5de934ccff148e02a7fdc80554a2fb

Initially I had a minimal schema and I had no issue. It looks like prisma relation system is introducing the bug.

[mcollina]

https://github.com/davidmarkclements/fast-safe-stringify/blob/0e011f068962e8f8974133a47afcabfc003f2183/index.js#L30-L47 has probably something wrong that makes Prisma unhappy.

I think this is the same problem of davidmarkclements/fast-safe-stringify#46 and davidmarkclements/fast-safe-stringify#43. On the first there is definitely a hint on a potential fix at the end.

Unfortunately I do not have time right now to diagnose and fix this, I would be extremely happy to get a PR.

[davidmarkclements]

thanks for your efforts @SebastienElet - I'm in a similar place to @mcollina - but if you don't have time to PR but do have time to isolate further and share your analysis we can hopefully resolve it sooner

[simoneb]

I did a quick investigation of this and posting the result here.

• the popular safe-json-stringify has the same issue as fast-safe-stringify
• @bugsnag/safe-json-stringify, a fork of the above which includes a hard limit on object depth/breadth, handles it properly
• a plain JSON.stringify with a simple replacer that handles cycles works fine

Based on this, it looks like the issue seems to be related to the deeply nested nature of the prism object that's being logged. I'm not sure why the popular safe-json-stringify and @davidmarkclements 's fast-safe-stringify are not handling this properly, considering that a replacer which handles cycles and makes this work is a few lines of code, but I guess it's for some performance optimization of some sort which I'm not aware of.

[davidmarkclements]

ah so then it may not be infinite recursion, it may be that depth is greater than max stack size.

We don't use the replacer for performance reasons. The hard limit sort of is the max stack size, but I'm not sure you can actually catch that error and rethrow it, if we could it would be useful because we could change the message to "object depth too great"

But it's happening in decirc which suggest a circular reference is still involved somewhere - maybe we can at least circuit break that some way

[jackmurdoch]

I've looked into this quickly, and replacing lines https://github.com/davidmarkclements/fast-safe-stringify/blob/master/index.js#L50-L54 in fast-safe-stringify with...

if (Array.isArray(val)) {
  for (i = 0; i < val.length; i++) {
    stack.push(val[i])
    decirc(val[i], i, stack, val)
    stack.pop()
  }
}

...fixes the problem described in this ticket. However, I'm not sure if this is the correct approach or what side effects this has. I no longer have the time to test further.

[mcollina]

can you open a PR?

[matus-sabo]

I've looked into this quickly, and replacing lines https://github.com/davidmarkclements/fast-safe-stringify/blob/master/index.js#L50-L54 in fast-safe-stringify with...

if (Array.isArray(val)) {
  for (i = 0; i < val.length; i++) {
    stack.push(val[i])
    decirc(val[i], i, stack, val)
    stack.pop()
  }
}

...fixes the problem described in this ticket. However, I'm not sure if this is the correct approach or what side effects this has. I no longer have the time to test further.

This is not correct fix it has side effects, it just add circular to all array items, no matter if really circular, ex.

const pino = require("pino");

const test = {
  array: [
    {
      some: "test",
      circular: [],
    },
  ],
};

test.array[0].circular.push(test);

 const logger = pino();
 logger.info("logger works");
 logger.info({ test });
 logger.info("logger works");

Will result into without fix:

{"level":30,"time":1618409713665,"pid":11189,"hostname":"edkos-iMac.local","msg":"logger works"}
{"level":30,"time":1618409713665,"pid":11189,"hostname":"edkos-iMac.local","test":{"array":[{"some":"test","circular":["[Circular]"]}]}}
{"level":30,"time":1618409713666,"pid":11189,"hostname":"edkos-iMac.local","msg":"logger works"}

Will result into with suggested fix:

{"level":30,"time":1618408097846,"pid":10869,"hostname":"edkos-iMac.local","msg":"logger works"}
{"level":30,"time":1618408097847,"pid":10869,"hostname":"edkos-iMac.local","test":{"array":["[Circular]"]}}
{"level":30,"time":1618408097847,"pid":10869,"hostname":"edkos-iMac.local","msg":"logger works"}

[matus-sabo]

I removed all the http layer and only the prisma client is involved.
I have a minimal example available here : https://gist.github.com/SebastienElet/8e5de934ccff148e02a7fdc80554a2fb

Initially I had a minimal schema and I had no issue. It looks like prisma relation system is introducing the bug.

I run this test and this is not CPU hang, at first glance it seems like it hang a process, but after a few mins it actually move on crash with:

UnhandledPromiseRejectionWarning: RangeError: Invalid string length
    at JSON.stringify (<anonymous>)
    at stringify (/Users/edko/Sandbox/Nearform/fast-safe-stringify-test/node_modules/fast-safe-stringify/index.js:14:16)
    at stringify (/Users/edko/Sandbox/Nearform/fast-safe-stringify-test/node_modules/pino/lib/tools.js:401:12)
    at Pino.asJson (/Users/edko/Sandbox/Nearform/fast-safe-stringify-test/node_modules/pino/lib/tools.js:139:45)
    at Pino.write (/Users/edko/Sandbox/Nearform/fast-safe-stringify-test/node_modules/pino/lib/proto.js:166:28)
    at Pino.LOG [as info] (/Users/edko/Sandbox/Nearform/fast-safe-stringify-test/node_modules/pino/lib/tools.js:55:21)
    at start (/Users/edko/Sandbox/Nearform/fast-safe-stringify-test/index.js:39:10)
    at Object.<anonymous> (/Users/edko/Sandbox/Nearform/fast-safe-stringify-test/index.js:45:1)
    at Module._compile (internal/modules/cjs/loader.js:1063:30)
    at Object.Module._extensions..js (internal/modules/cjs/loader.js:1092:10)

I think fast-safe-stringify decirc function works properly (I checked the code), but input object is very big to process and stringify to output.
We need to set some limits on how deep we will parse the object as @simoneb suggested in #990 (comment), what do you think @mcollina?

[simoneb]

@lamanabie that's correct and in line with the earlier analysis

[mcollina]

I would be ok in adding an option to fast-safe-stringify.

[simoneb]

@SebastienElet I tried the fix implemented in davidmarkclements/fast-safe-stringify#56 inside your repro and it works fine.

If you could confirm we'll close this issue as soon as a new version is released and integrated in pino.

[simoneb]

@SebastienElet this fix is now in version 2.1.0 of https://github.com/davidmarkclements/fast-safe-stringify

[mcollina]

I had to change the default depth and edge limit in fast-safe-stringify because it broke folks. I'm going to send a PR to set them in pino instead.

[github-actions]

This issue has been automatically locked since there has not been any recent activity after it was closed. Please open a new issue for related bugs.