Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

CPU Hang with infinite decirc #990

Closed
SebastienElet opened this issue Mar 24, 2021 · 25 comments · Fixed by #1169
Closed

CPU Hang with infinite decirc #990

SebastienElet opened this issue Mar 24, 2021 · 25 comments · Fixed by #1169
Labels

Comments

@SebastienElet
Copy link

SebastienElet commented Mar 24, 2021

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
Capture d’écran 2021-03-24 à 13 51 32

@davidmarkclements
Copy link
Member

davidmarkclements commented Mar 24, 2021 via email

@mcollina
Copy link
Member

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

@mcollina
Copy link
Member

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

@mcollina
Copy link
Member

@mcollina mcollina added the bug label Mar 24, 2021
@SebastienElet
Copy link
Author

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
Copy link
Member

davidmarkclements commented Mar 24, 2021 via email

@mcollina
Copy link
Member

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

@SebastienElet
Copy link
Author

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
Copy link
Member

Thanks, that would be really helpful.

@SebastienElet
Copy link
Author

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
Copy link
Member

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
Copy link
Member

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
Copy link
Contributor

simoneb commented Mar 29, 2021

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

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
Copy link
Member

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
Copy link

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
Copy link
Member

can you open a PR?

@simoneb

This comment has been minimized.

@matus-sabo
Copy link
Contributor

matus-sabo commented Apr 14, 2021

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
Copy link
Contributor

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
Copy link
Contributor

simoneb commented Apr 14, 2021

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

@mcollina
Copy link
Member

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

@simoneb
Copy link
Contributor

simoneb commented Sep 7, 2021

@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
Copy link
Contributor

simoneb commented Sep 7, 2021

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

@mcollina mcollina closed this as completed Sep 7, 2021
@mcollina mcollina reopened this Sep 8, 2021
@mcollina
Copy link
Member

mcollina commented Sep 8, 2021

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
Copy link

github-actions bot commented Feb 2, 2022

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.

@github-actions github-actions bot locked as resolved and limited conversation to collaborators Feb 2, 2022
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
Projects
None yet
Development

Successfully merging a pull request may close this issue.

6 participants