Under Pressure

[refaelos]

Hey,

I have a question and i'm not sure it's related to winston or to the way node.js works.

Why does this fail?

for (var i=0; i<10000000000; i++) logger.info('some message ' + i);

It starts running fine but after some time it's just stuck.

[indexzero]

Can you give us more context? e.g.: what transports do you have setup with that logger instance?

[refaelos]

Regular file transport.

var logger = new (winston.Logger)({
  transports: [
    new (winston.transports.File)({ filename: filename })
  ]
});

[pose]

@refaelos can you try with the following snippet in order to see if there are any errors during logging?

for (var i=0; i<10000000000; i++) {
  logger.info('some message ' + i, function (err) {
    console.log(err);
  });
}

Thanks in advance,

[refaelos]

Stuck ... 😕

[joseph-norman]

So I saw this issue and I've been messing around with it. Here's what I was trying out:

var winston = require('winston');
var filename = 'test.txt';

var logger = new (winston.Logger) ({
  transports: [
    new (winston.transports.File) ({ filename: filename })
  ]
  });

for (var i = 0; i < 10000000000; i++) {
  console.log('starting log');
  logger.info('some message' + i, function (err) {
    if (err) { console.log(err); }
  });
}

I tried with a few other variants that worked fine, such as changing the value of i to significantly less than the above number. I'm noticing that the log file isn't created until the loop is finished (discovered this from increasing the value of i to one extra zero on the end, starting at 100 onwards, where the time to run the app increased significantly).

So I don't think it's sticking, I think it just doesn't produce the file as you'd expect it to (i.e. create it first, then add to it on each iteration).

[indexzero]

@joseph-norman could you try writing a single line, then when that is done, writing 10000000000 lines? I think this may have to do with our initial buffering before flushing to the file upon create.

[joseph-norman]

@indexzero I'll give this a go now

[joseph-norman]

So I added the following to what I had before:

logger.info("one liner", function (err) {
  if (err) {
    console.log(err);
  }
});

There's no file being created in this instance either - the loop is ran immediately afterwards. Obviously this kind of loop is going to be CPU intensive (checking top and I'm seeing an almost constant 100% core usage). I imagine that eventually a file will be created when the buffer is flushed; after this loop is finished.

edit: changed the loop increment count value to 100, and can see both log entries - just for consistency.

[indexzero]

Duplicate of #288, which is now fixed.