Logging in the separate thread

[ed-fruty]

Is it possible to delegate logging to separate thread in NodeJS using Winston out of the box?

I want to minimize blocking operations and other side affects for performance.

And I think about moving logging to the separate thread.

const winston = require('winston');
const { Worker, isMainThread,  workerData } = require('worker_threads');

class MyLogger
{
    info(message) {
        if (isMainThread) {
            this.thread = new Worker(__filename)
        } else {
            this.getLoggerInstance().info(message);
        }
    }

    getLoggerInstance() {
        if (! this.logger) {
            this.logger = winston.createLogger({
                level: 'info',
                format: winston.format.json(),
                defaultMeta: { service: 'user-service' },
                transports: [
                    new winston.transports.File({ filename: 'error.log', level: 'error' }),
                    new winston.transports.File({ filename: 'combined.log' })
                ]
            });
        }
        return this.logger;
    }
}

// USAGE
const myLogger = new MyLogger();

myLogger.info('something I want to log');

Does anyone tries to do the same?

Do you know any limitations?

Will it help for performance?

[bjeromeHCS]

I tried this out of curiosity and my first message never got logged.. not sure why. I'm using Node v10.15 with the --experimental-worker flag.

Logger.js

const { createLogger, format, transports } = require('winston');
const { combine, timestamp, printf } = format;
const { Worker, isMainThread, parentPort } = require('worker_threads');
const logFormat = printf(({ level, message, timestamp }) => {
  return `${timestamp} [${level.toUpperCase()}]: ${message}`;
});

class Logger {
 log(message) {
    if (isMainThread && !this.thread) {
      this.thread = new Worker(__filename);
    } else {
      this.getLogger().info(message);
    }
 }

  getLogger() {
    if (!this.logger) {
      this.logger = createLogger({
        level: 'info',
        transports: [
          new transports.Console({
            format: combine(
              timestamp(),
              logFormat,
            ),
          })
        ]
      });
    }

    return this.logger;
  }
}

exports.Logger = Logger;

index.js

const { Logger } = require('Logger');

const logger = new Logger();

logger.log('my test message');
logger.log('my test 2 message');
logger.log('my foo message');
logger.log('my bar message');

output

2019-05-01T18:39:26.865Z [INFO]: my test 2 message
2019-05-01T18:39:26.871Z [INFO]: my foo message
2019-05-01T18:39:26.871Z [INFO]: my bar message

[bjeromeHCS]

It seems the first log is running on the main thread. If i remove the else so it's now:

  log(message) {
    if (isMainThread && !this.thread) {
      this.thread = new Worker(__filename);
    }
    this.getLogger().info(message);
  }

then it works. There might just be a better way to do this.

[NotMoni]

I would also like have the logger run on a sperate thread.

[Saeger]

There is a new logger called "pino" which does exactly the initial intention of this post, by actually writing logs in a separate thread with worker threads. Check it out here: https://github.com/pinojs/pino

[cjbarth]

Pino has been around for a while and works well, however, because it logs in a separate thread it may actually create issues for some types of applications.

For example, if you are working with a worker pool, depending on how you configure your logger and your pool, you can have messages interleaved in unexpected ways and you might have less resources available to process incoming connections due to a smaller pool size. A separate thread isn't always the correct solution; the entire system must be looked at together.

Case in point, if you log to syslog, then there is very little logging overhead for Node. Granted, you still have to transform the object, but then, as fast as it can be written to a socket, it is out of Node's hands. The overhead of transforming the object would need to be done in some form if you tried to get that object to another thread to have it logged from there. So, you save yourself nothing.

In fact, you could easily say that syslog would be the multi-threaded solution :)