NodeJS winston logging large number of writes bogs down

Question

Node JS - 12.7 Winston - 1.0.1

I am struggling with trying to generate "fake" log files representing many "devices". Basically I am going to use the data for testing and visualization in Kibana.

I set my Winston up to log to file as so:

var winston = require('winston');

var logger = new (winston.Logger)({
transports: [
    new (winston.transports.File)({
        filename: 'logs/dsm.log'
    })
  ]
});

So I have an array of devices which is just a list 12-byte hashes like: AB4576D4C6AC, etc.

I am looping through the device array and assembling my "fake" log entry like so:

for (var i = 0; i < devices.length; i++) {
    var timeStmp = startDateTime.clone().add((i * config.dsmIntervalMinutes), "m");
    dsm = {
        deviceId: devices[i].deviceId,
        msg: "some log entry text",
        timeStmp: timeStmp
    };
    logger.info(dsm);
}

As you can see, I end by logging the message as info to Winston after each DSM is created in the loop.

So this seems to work fine, except when I have a large number of devices. I want to get up to 1m devices or so. I am currently struggling to do 100k.

What I see is that the node process is not writing the logs to the log file. It seems to be storing them all in memory (as seen by using top) and once it gets to 10k or so it slows to a crawl and eventually stops progressing. The log file is never written.

So I am wondering if there is a way to do this? Can I somehow force node/winston to stop and write to disk every once in a while? Like flush the cache? I don't see options in winston for this.

Any help would be greatly appreciated!

Answer 1

The problem here isn't quite that the loop is synchronous, it's that you need to stop writing to the underlying fs.createWriteStream instance when it is flushing to disk. By not waiting you continue to fill up the internal buffer which is why your memory usage is increasing without bound.

So with that in mind, the code sample becomes:

var fs = require('fs');
var winston = require('winston');

var stream = fs.createWriteStream('logs/dsm.log');
var file = new (winston.transports.File)({ stream: stream });
var logger = new (winston.Logger)({ transports: [file] });

//
// We'll store this for our position in all devices across
// `drain` events from the stream.
//
var curr = 0;

//
// function isFlushing()
// Returns a value if the file is flushing
//
function isFlushing() {
  var state = stream._writeableState;
  return state.length < state.highWaterMark;
}

//
// function logDevice()
// Logs a single device and returns a value
// indicating if the underlying filestream is full.
//
function logDevice(d) {
  var timeStmp = startDateTime.clone().add((i * config.dsmIntervalMinutes), 'm');  
  logger.info({
    deviceId: d.deviceId,
    msg: 'some log entry text',
    timeStmp: timeStmp
  });

  return isFlushing();
}

(function logAllDevices() {
  for (; curr < devices.length; curr++) {
    if (!logDevice(devices[curr])) {
      stream.once('drain', logAllDevices);
      break;
    }
  }
})();