FATAL ERROR: CALL_AND_RETRY_2 Allocation failed - process out of memory #668

ScorpioKing · 2015-07-17T04:26:43Z

Hello,
I am using File Transport.

My Code Snippet

for(var i = 0 ; i < 1000000 ; i++){
    logger.debug("DEBUG JJ: ",i);
    //Some calculations over here
};

After executing this code i am getting

OUTPUT :
FATAL ERROR: CALL_AND_RETRY_2 Allocation failed - process out of memory
Aborted

As i am iterating using for loop and taking logs into file, winston is doing so much of file write operation.

Please tell me some solution for this.

The text was updated successfully, but these errors were encountered:

chjj · 2015-07-17T05:16:53Z

@ScorpioKing, could we see a full gist of the code?

I'm guessing either the file stream isn't opened fast enough (or at all), or it's not flushing fast enough: the logs end up getting buffered.

(Or, there's some strange memory leak with hanging reachable variables in the FileTransport.{log,_write} methods, but I doubt it).

Best way to test this would be to rip out all the buffering code in the file transport and run @ScorpioKing's code. Thoughts?

ScorpioKing · 2015-07-17T06:05:32Z

@chjj
This is my code :

for(var i = 0 ; i < 1000000 ; i++){
    logger.debug("DEBUG JJ: ",i);
    if (n < 2 ) {
        logger.debug("Not a prime number !!!");
    }else{
        // Now assume that n is prime, we will try to prove that it is not.
        var isPrime = true;
        // Now check every whole number from 2 to the square root of n. If any of these divides n exactly, n cannot be prime.
        for (var i = 2; i <= Math.sqrt(n); i++) {
            if (n % i == 0) {
                isPrime = false;
            }

        }
        if(isPrime){
            logger.debug("Prime number !!!");
        }else{
            logger.debug("Not a prime number !!!");
        }

    }

};

If i comment out whole code and put this only

for(var i = 0 ; i < 1000000 ; i++){
    logger.debug("DEBUG JJ: ",i);
};

Then also i am getting this

OUTPUT :
FATAL ERROR: CALL_AND_RETRY_2 Allocation failed - process out of memory
Aborted

ghost · 2015-12-06T07:55:58Z

I met this problem as well.

Code:

main.js

(function(){
    "use strict";

    let logger = require("./winston-config");

    for(let i = 0; i < 1000000 ; i++){
        logger.log("silly", "Silly message " + i + ".");
        logger.log("debug", "Debug message " + i + ".");
        logger.log("verbose", "Verbose message " + i + ".");
        logger.info("Info message " + i + ".");
        logger.warn("Warn message " + i + ".");
        logger.error("Error message " + i + ".");
    }

    logger = null;

})();

winston-config.js

module.exports = (function(){
    "use strict";
    let Winston = require("winston");
    let logger = new (Winston.Logger)({
        "transports" : [
            new (Winston.transports.Console)({
                "colorize" : true
                ,"timestamp" : true
                ,"showLevel": true
                ,"level" : "debug"
            })
            ,new (Winston.transports.File)({
                "name" : "winston-file"
                ,"filename" : "./logs/winston_size.log"
                ,"maxSize" : 1024
                ,"maxFiles" : 1024
                ,"timestamp" : true
                ,"showLevel": true
                ,"level": "silly"
            })
        ]
    });
    return logger;
})();

Run

node main.js

Exception Console

pic

text

2015-12-06T07:43:52.129Z - warn: Warn message 159172.
2015-12-06T07:43:52.129Z - error: Error message 159172.
2015-12-06T07:43:52.129Z - debug: Debug message 159173.
2015-12-06T07:43:52.129Z - verbose: Verbose message 159173.
2015-12-06T07:43:52.129Z - info: Info message 159173.
2015-12-06T07:43:52.130Z - warn: Warn message 159173.
2015-12-06T07:43:52.130Z - error: Error message 159173.
2015-12-06T07:43:52.130Z - debug: Debug message 159174.
2015-12-06T07:43:52.130Z - verbose: Verbose message 159174.

<--- Last few GCs --->

  306828 ms: Scavenge 1397.8 (1456.6) -> 1397.8 (1456.6) MB, 3.2 / 0 ms (+ 3.0 ms in 1 steps since l
ast GC) [allocation failure] [incremental marking delaying mark-sweep].
  307734 ms: Mark-sweep 1397.8 (1456.6) -> 1397.8 (1456.6) MB, 905.9 / 0 ms (+ 4.0 ms in 2 steps sin
ce start of marking, biggest step 3.0 ms) [last resort gc].
  308648 ms: Mark-sweep 1397.8 (1456.6) -> 1397.8 (1456.6) MB, 914.4 / 0 ms [last resort gc].


<--- JS stacktrace --->

==== JS stack trace =========================================

Security context: 000000324D144A59 <JS Object>
    2: STRING_ADD_LEFT(aka STRING_ADD_LEFT) [native runtime.js:134] [pc=0000024F0834D5BE] (this=0000
00A3314E3031 <String[20]: 2015-12-06T07:43:52.>,g=135)
    3: toISOString [native date.js:~503] [pc=0000024F08364079] (this=000000A3314E3059 <a Date with m
ap 000000A2B9E0D6E1>)
    4: /* anonymous */(aka /* anonymous */) [e:\workspace_nodejs\winston-learning\node_modules\winst
on\lib\winston\com...

FATAL ERROR: CALL_AND_RETRY_LAST Allocation failed - process out of memory

Note

When any exception happened, no log file (nothing at all) would be generated.

Versions:

node@5.1.1
winston@2.1.1
win7 64bit

Thanks

indexzero · 2015-12-06T08:02:32Z

Why are these results surprising to you? You are attempting to log one million messages in a single node process in the same tick.

Do you get one million requests per millisecond in your web application?

tjwebb · 2016-02-13T03:35:35Z

FWIW, I'm seeing the same thing with much more modest output (a couple ES6 classes), and logging to console. trailsjs/trailpack-repl#20. Using console.log() works fine.

ghost · 2016-02-13T08:54:21Z

@tjwebb, the root cause is that, console.log() is synchronized call, while winstonjs and log4js are asynchronized. It means, it needs a chance to do the underlying writing, or the content will be buffered until the memory ran out.

Root Cause

This is caused by the event loop mechanisms of nodejs, bool ev_run (loop, int flags), it takes an task
from watchers each time by this order:

idle -> I/O -> check

The 'for' and 'process.nextTick()' are idle watchers, so the
logger doesn't have a chance to do the underlying I/O work. And it
cause the memory running out.

Solution

So, we need to give the logger a chance to do the underlying work.

example main.js for winston

(function(){
    "use strict";

    const WORK_DONE_EVENT_NAME = "work-done";
    const WORK_TIMES = 100 * 1000 * 1000;

    let evem = new (require("events").EventEmitter)();
    let logger = require("./winston-config");

    // Explicitly listening on the event.
    evem.on(WORK_DONE_EVENT_NAME, function(){
        // setImmediate: after I/O operations
        setImmediate(doWork);
    });

    let idx = 0;
    function doWork(){
        idx++;
        if(idx >= WORK_TIMES){
            console.timeEnd(WORK_TIMES);
            return;
        }
        logger.silly(idx, function(err, level, msg, meta){
            if(err){
                throw err;
            }
            evem.emit(WORK_DONE_EVENT_NAME);
        });
    }

    console.time(WORK_TIMES);
    doWork();
})();

tjwebb · 2016-02-13T19:03:54Z

@alphatan have you tested this fix? For me, this only happens when I have the REPL running. console.log works, and winston without the REPL works. but Winston + REPL = bad.

My process doesn't just run out of memory, it hangs for about 3-4 minutes and then crashes with that error. I guess in that time it's in some sort of infinite loop. Why would this behavior result from winston not being able to write its output in a single tick?

Also fwiw, this occurs in both node 4 and 5.

tjwebb · 2016-02-13T19:20:55Z

This issue is really confusing. For example, this works fine for me:

    let arr = [ ]
    for (let i = 0; i < 100000; i++) {
      arr.push(function () { })
    }
    app.log.debug(arr)

But logging two instantiated ES6 classes with two static properties fails. It can't be only about object size.

tjwebb · 2016-02-13T19:24:14Z

This is interesting. So my line

app.log(app.models)

Fails in the above way. However, if I first wrap it in JSON.stringify(), I see this first:

Debug: internal, implementation, error
    TypeError: Uncaught error: Converting circular structure to JSON
    at Object.stringify (native)

Could it be that winston isn't handling this properly, and it's sending it into this kind of tailspin?

tjwebb · 2016-02-13T19:30:21Z

@indexzero it looks like, in my case, this is resulting from an unhandled exception in winston. If I disable prettyPrint and colorize, instead of hanging forever, I now see this:

Debug: internal, implementation, error
    TypeError: Uncaught error: Cannot convert a Symbol value to a string

It's failing here: https://github.com/winstonjs/winston/blob/master/lib/winston/common.js#L325. In ES6 (node 4 and later) there are new built-in types in addition to the ones that winston is specifically looking for, and it's choking. For example, we cannot assume that object keys are only strings. As far as why/how this metatsizes into a giant memory leak, I have no idea.

tjwebb · 2016-02-13T19:49:25Z

@indexzero I updated common.js to detect Symbols using typeof, and everything now works with prettyPrint disabled. If I enable prettyPrint, my node process still hangs and crashes.

I'll do a bit more research and see if I can find out why prettyPrint is causing things to break

pankaj20dec · 2016-04-12T13:02:10Z

I am setting up telescope on my localhost. When I am downloading meteor using cmd then I am getting
above issue. Anyone can help me ??

lucasrenan · 2016-07-14T23:29:21Z

is this problem related to nodejs/node#3524 (comment) ?

indexzero added the Needs Investigation label Oct 29, 2015

indexzero closed this as completed Dec 6, 2015

tjwebb mentioned this issue Feb 13, 2016

winston cannot render the Symbol type #805

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

FATAL ERROR: CALL_AND_RETRY_2 Allocation failed - process out of memory #668

FATAL ERROR: CALL_AND_RETRY_2 Allocation failed - process out of memory #668

ScorpioKing commented Jul 17, 2015

chjj commented Jul 17, 2015

ScorpioKing commented Jul 17, 2015

ghost commented Dec 6, 2015

indexzero commented Dec 6, 2015

tjwebb commented Feb 13, 2016

ghost commented Feb 13, 2016

tjwebb commented Feb 13, 2016

tjwebb commented Feb 13, 2016

tjwebb commented Feb 13, 2016

tjwebb commented Feb 13, 2016

tjwebb commented Feb 13, 2016

pankaj20dec commented Apr 12, 2016

lucasrenan commented Jul 14, 2016

FATAL ERROR: CALL_AND_RETRY_2 Allocation failed - process out of memory #668

FATAL ERROR: CALL_AND_RETRY_2 Allocation failed - process out of memory #668

Comments

ScorpioKing commented Jul 17, 2015

chjj commented Jul 17, 2015

ScorpioKing commented Jul 17, 2015

ghost commented Dec 6, 2015

indexzero commented Dec 6, 2015

tjwebb commented Feb 13, 2016

ghost commented Feb 13, 2016

tjwebb commented Feb 13, 2016

tjwebb commented Feb 13, 2016

tjwebb commented Feb 13, 2016

tjwebb commented Feb 13, 2016

tjwebb commented Feb 13, 2016

pankaj20dec commented Apr 12, 2016

lucasrenan commented Jul 14, 2016