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

[Bug]: possibile memory leak leads to node process exit in express.js web app #2237

Open
mkjsix opened this issue Nov 9, 2022 · 8 comments

Comments

@mkjsix
Copy link

mkjsix commented Nov 9, 2022

🔎 Search Terms

winston memory leak

The problem

After replacing console.log with winston 3.8.2 we are experiencing a sudden exit of the node process with this error:

66|happyde | api: (node:25295) UnhandledPromiseRejectionWarning: RangeError: Invalid string length
66|happyde | api:     at stringifyFnReplacer (/home/admin/ci-cd/dev.int.goomood.tech/node_modules/safe-stable-stringify/index.js:316:68)
66|happyde | api:     at stringifyFnReplacer (/home/admin/ci-cd/dev.int.goomood.tech/node_modules/safe-stable-stringify/index.js:273:23)
66|happyde | api:     at stringifyFnReplacer (/home/admin/ci-cd/dev.int.goomood.tech/node_modules/safe-stable-stringify/index.js:314:23)
66|happyde | api:     at stringify (/home/admin/ci-cd/dev.int.goomood.tech/node_modules/safe-stable-stringify/index.js:659:18)
66|happyde | api:     at Format.transform (/home/admin/ci-cd/dev.int.goomood.tech/node_modules/logform/json.js:28:19)
66|happyde | api:     at DerivedLogger._transform (/home/admin/ci-cd/dev.int.goomood.tech/node_modules/winston/lib/winston/logger.js:313:29)
66|happyde | api:     at DerivedLogger.Transform._read (/home/admin/ci-cd/dev.int.goomood.tech/node_modules/winston/node_modules/readable-stream/lib/_stream_transform.js:177:10)
66|happyde | api:     at DerivedLogger.Transform._write (/home/admin/ci-cd/dev.int.goomood.tech/node_modules/winston/node_modules/readable-stream/lib/_stream_transform.js:164:83)
66|happyde | api:     at doWrite (/home/admin/ci-cd/dev.int.goomood.tech/node_modules/winston/node_modules/readable-stream/lib/_stream_writable.js:409:139)
66|happyde | api:     at writeOrBuffer (/home/admin/ci-cd/dev.int.goomood.tech/node_modules/winston/node_modules/readable-stream/lib/_stream_writable.js:398:5)
66|happyde | api: (node:25295) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). To terminate the node process on unhandled promise rejection, use the CLI flag `--unhandled-rejections=strict` (see https://nodejs.org/api/cli.html#cli_unhandled_rejections_mode). (rejection id: 4)

This is the JS stacktrace:

66|happyde | api: <--- Last few GCs --->
66|happyde | api: 7)[25295:0x4631f10]   728896 ms: Mark-sweep (reduce) 1935.8 (1943.6) -> 1935.4 (1943.2) MB, 3471.9 / 0.1 ms  (+ 0.0 ms in 1 steps since start of marking, biggest step 0.0 ms, walltime since start of marking 3472 ms) (average mu = 0.076, current mu = 0.000) [25295:0x4631f10]   733185 ms: Mark-sweep (reduce) 1936.8 (1940.6) -> 1936.8 (1942.6) MB, 4286.2 / 0.0 ms  (+ 0.0 ms in 16 steps since start of marking, biggest step 0.0 ms, walltime since start of marking 4289 ms) (average mu = 0.035, current mu = 0.001)
66|happyde | api: <--- JS stacktrace --->
66|happyde | api: FATAL ERROR: MarkCompactCollector: young object promotion failed Allocation failed - JavaScript heap out of memory
66|happyde | api:  1: 0xa3ac10 node::Abort() [/usr/bin/node]
66|happyde | api:  2: 0x970199 node::FatalError(char const*, char const*) [/usr/bin/node]
66|happyde | api:  3: 0xbba58e v8::Utils::ReportOOMFailure(v8::internal::Isolate*, char const*, bool) [/usr/bin/node]
66|happyde | api:  4: 0xbba907 v8::internal::V8::FatalProcessOutOfMemory(v8::internal::Isolate*, char const*, bool) [/usr/bin/node]
66|happyde | api:  5: 0xd76b25  [/usr/bin/node]
66|happyde | api:  6: 0xda74be v8::internal::EvacuateNewSpaceVisitor::Visit(v8::internal::HeapObject, int) [/usr/bin/node]
66|happyde | api:  7: 0xdb34f6 v8::internal::FullEvacuator::RawEvacuatePage(v8::internal::MemoryChunk*, long*) [/usr/bin/node]
66|happyde | api:  8: 0xd9f68f v8::internal::Evacuator::EvacuatePage(v8::internal::MemoryChunk*) [/usr/bin/node]
66|happyde | api:  9: 0xd9f908 v8::internal::PageEvacuationTask::RunInParallel(v8::internal::ItemParallelJob::Task::Runner) [/usr/bin/node]
66|happyde | api: 10: 0xd921e9 v8::internal::ItemParallelJob::Run() [/usr/bin/node]
66|happyde | api: 11: 0xdb5450 void v8::internal::MarkCompactCollectorBase::CreateAndExecuteEvacuationTasks<v8::internal::FullEvacuator, v8::internal::MarkCompactCollector>(v8::internal::MarkCompactCollector*, v8::internal::ItemParallelJob*, v8::internal::MigrationObserver*, long) [/usr/bin/node]
66|happyde | api: 12: 0xdb5cec v8::internal::MarkCompactCollector::EvacuatePagesInParallel() [/usr/bin/node]
66|happyde | api: 13: 0xdb5eb5 v8::internal::MarkCompactCollector::Evacuate() [/usr/bin/node]
66|happyde | api: 14: 0xdc7eb1 v8::internal::MarkCompactCollector::CollectGarbage() [/usr/bin/node]
66|happyde | api: 15: 0xd84178 v8::internal::Heap::MarkCompact() [/usr/bin/node]
66|happyde | api: 16: 0xd85c68 v8::internal::Heap::CollectGarbage(v8::internal::AllocationSpace, v8::internal::GarbageCollectionReason, v8::GCCallbackFlags) [/usr/bin/node]
66|happyde | api: 17: 0xd87ba5 v8::internal::Heap::HandleGCRequest() [/usr/bin/node]
66|happyde | api: 18: 0xd2e0b7 v8::internal::StackGuard::HandleInterrupts() [/usr/bin/node]
66|happyde | api: 19: 0x109f7a3 v8::internal::Runtime_StackGuard(int, unsigned long*, v8::internal::Isolate*) [/usr/bin/node]
66|happyde | api: 20: 0x1448f59  [/usr/bin/node]
66|happyde | api: Aborted
66|happyde | api: error Command failed with exit code 134.
66|happyde | lerna ERR! yarn run start:prod exited 134 in 'api'
66|happyde | lerna WARN complete Waiting for 1 child process to exit. CTRL-C to exit immediately.
66|happyde | error Command failed with exit code 134.

This is the winston configuration:

const winston = require('winston');
require('winston-daily-rotate-file');

// Define different colors for each level.
const colors = {
    error: 'white redBG',
    warn: 'yellow',
    info: 'green',
    http: 'magenta',
    verbose: 'cyan',
    debug: 'white cyanBG',
    sylly: 'white'
}

winston.addColors(colors);

// This method set the current severity based on the current NODE_ENV
const level = () => {
    const logLevel = process.env.LOG_LEVEL || 'info';
    return logLevel;
}

// Chose the aspect of your log customizing the log format.
const format = winston.format.combine(
    // Add the message timestamp with the preferred format
    winston.format.timestamp({ format: 'YYYY-MM-DD HH:mm:ss:ms' }),
    // Define the format of the message showing the timestamp, the level and the message
    winston.format.printf(
        (info) => `${info.timestamp} ${info.level}: ${info.message}`
    )
)

// Create the logger instance that has to be exported
// and used to log messages.
const logger = winston.createLogger({
    level: level(),
    transports: [
        new winston.transports.DailyRotateFile({
            filename: 'logs/server-%DATE%.log',
            datePattern: 'YYYY-MM-DD',
            zippedArchive: true,
            maxSize: '20m',
            maxFiles: '30d',
            createSymlink: true,
            format: winston.format.combine(
                winston.format.uncolorize(),
                format
            )
        }),
        new winston.transports.Console({
            format: winston.format.combine(
                winston.format.colorize(),
                format
            )
        })
    ]
});

module.exports = logger

What version of Winston presents the issue?

v3.8.2

What version of Node are you using?

v14.20.1

If this worked in a previous version of Winston, which was it?

No response

Minimum Working Example

This is the app.ts

import express from "express";
import cors from "cors";
import fileUpload from "express-fileupload";
import request from "./macros/request";
import response from "./macros/response";
import logger from "./config/logger";
import morgan from "morgan";

const app = express();

logger.info('Initiliazing middlewares ...');
logger.debug('process.env: ' + JSON.stringify(process.env, null, 2));
logger.info(`NODE_ENV = '${process.env.NODE_ENV}', Logger.level = '${logger.level}'`);

const stream = {
    // Use the http severity log level for morgan
    write: (message) => logger.http(message),
};
app.use(morgan('combined', { stream }));

app.use(cors());

app.use(
    fileUpload({
        parseNested: true,
        debug: process.env.NODE_ENV == "development"
    })
);

app.use(
    express.json({
        verify: (request: any, response, buffer) => {
            // stripe webhook signature validation works with raw body
            if (request.url.includes("webhook")) {
                request.rawBody = buffer;
            }
        }
    })
);

app.use(request);
app.use(response);

export default app;

Additional information

No response

@mkjsix
Copy link
Author

mkjsix commented Nov 10, 2022

As additional information, the problem was a big stopper for us so we moved to another logging library (pino) and the memory problem disappeared.

@YasiOnFire
Copy link

I'm sadly experiencing same issue. For me it exits the node process if I try to log an instance of AxiosError.

@and2352000
Copy link

I'm sadly experiencing same issue. For me it exits the node process if I try to log an instance of AxiosError.

Facing same issue too. I move to pino and problem is solved.

@foreverest
Copy link

foreverest commented Sep 27, 2023

Same issue, memory is leaking. Any plans to fix this?

@foreverest
Copy link

In my case memory was leaking due to improper creation of logger instances.

I created a shared logger options object and used it to instantiate multiple loggers in my code:

export const defaultLoggerOptions: winston.LoggerOptions = {
  ...
  transports: [new winston.transports.Console()],
};

...

const logger = winston.createLogger(defaultLoggerOptions);

Specifically, it seems like winston.transports.Console() is not intended to be re-used between the logger instances. So, changing the code as follows fixed the issue for me.

export function getDefaultLoggerOptions(): winston.LoggerOptions {
  return {
    ...
    transports: [new winston.transports.Console()],
  };
}

...

const logger = winston.createLogger(getDefaultLoggerOptions());

@SudhirVeerakamaraj
Copy link

memory leak originates from one of the dependency package safe-stable-stringify in the method stringifyFnReplacer

image

@wbt
Copy link
Contributor

wbt commented Nov 8, 2023

Possibly related: BridgeAR/safe-stable-stringify#41 (which also cites a solution of using a maximumDepth option to safe-stable-stringify).
Can someone add a failing test case so it's clear what's being logged when the error occurs? A clearly reproducible example would help determine if any proposed fix actually fixes the issue; looking at OP above it seems to depend on the details of an incoming request.

@joao-moonward
Copy link

joao-moonward commented Jan 30, 2024

Hello everyone!
I found an error while using NestJs with the Winston library to format my logs. This is how I have set it up:

    this.logger = WinstonModule.createLogger({
      format: winston.format.uncolorize(),
      transports: [
        new winston.transports.Console({
          format: winston.format.combine(
            winston.format.timestamp(),
            winston.format.ms(),
            utilities.format.nestLike()
          ),
        }),
      ],
      level: "debug",
    });

Running it locally everything is working fine, and my memory heap is fine:
Screen Shot 2024-01-30 at 12 24 42 pm

Local env:

  • Node: v18.19.0
  • Mac: MacOs Monterey 12.3; M1, 2020; 8GB;

When I push it, I use a docker image, and this is what I have
Figure_1

It consumes all my heap memory. My container is using node:18.13-alpine.

In order to get this weird behaviour quickly I wrote this code inside my bootstrap function:

  setInterval(() => {
    console.error('test'.repeat(1000));
  }, 10);

  setInterval(() => {
    const MB_DIV = 1024 * 1024;
    const usage = process.memoryUsage();

    fs.appendFile(
      'message.txt',
      `${new Date().toISOString()} heap used/total: ${
        usage.heapUsed / MB_DIV
      }/${usage.heapTotal / MB_DIV} MB\r\n`,
      function (err) {
        if (err) throw err;
        console.log('Saved!');
      },
    );
  }, 1000);

Is there anything I'm missing that can cause this issue?

[update]
Do I have to explicitly use console.clear()?

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

No branches or pull requests

7 participants