[Question] How to use event system with logging library

[Darkproduct]

I currently use winston for all my logging needs and I would like to print a progress bar as well. I would like to just add a new ProgressBarConsoleTransport to winston, but I can't find a nice way to make this work. I read through some issues and pull requests, like #57.

The progress bar doesn't have an easy-to-use interrupt feature like node-progress, but provides more options and custom features.

From my understanding, the event system is implemented in the opposite direction. I would like to send an event to the progress bar every time there is a need to log something to the console, but instead, I get an event every time I can write something to the console. This means I would have to buffer all the logs somehow and write them all at once as soon as I am able to.

So my question really is, what would be the best way to make this library compatible with a logger like winston?

[AndiDittrich]

cli-progress is a gui-component and has nothing to do with logging itself. it's just a display for users.

for application "logging" in container/ci context there are the noTTY options noTTYOutput and notTTYSchedule available - this one can be used in conjunction with the events (or pass a custom output stream, or even better a custom terminal)

[Darkproduct]

My question is more related to #57, #85 and #99. Winston has multiple transports that can l log the messages to all kind of outputs as well as the console.

A typical config would look something like this:

export const logger = winston.createLogger({
  transports: [
    // Normal log file
    new winston.transports.File({
      filename: logfilepath,
      level: 'warn',
      handleExceptions: true,
      format: winston.format.combine(
        winston.format.splat(),
        winston.format.timestamp(),
        logformat
      )
    }),
    
    // Console logging
    new winston.transports.Console({
      format: winston.format.combine(
        winston.format.splat(),
        winston.format.colorize(),
        winston.format.simple()
      ),
      colorize: true,
      level: 'info'
    })
  ]
});

And all events from logger.error and logger.warn would be written to the console and the file, where logger.info is only written to the console. Currently, this is messing with every progress bar, because in the end this prints to the console just like console.log does.

It would be great to have an example of a log(msg) function that uses watson.Logger or console.log that works while a progress bar is running without messing everything up. I think @dlvoy in #57 hinted something like that, but I'm not sure how he solved it in the end.

[Darkproduct]

I made some progress, by wrapping the logger for the object that uses the progress bar like this:

class LoggerWrap {
  /**
   * A wrapper for any logger with an `log` method to work with cli-progress
   * @param {watson.Logger|Console} logger the logger instance
   */
  constructor(logger) {
    this.logger = logger;

    this.logArgs = new Array();
  }

  getCallback() {
    return () => {
      while (this.logArgs.length > 0) {
        const msg = this.logArgs.shift();
        this.logger.log(...msg);
      }
    };
  }

  log(...args) {
    this.logArgs.push(args);
  }

  error(msg, ...meta) { this.log('error', msg, ...meta); }
  warn(msg, ...meta) { this.log('warn', msg, ...meta); }
  info(msg, ...meta) { this.log('info', msg, ...meta); }
  http(msg, ...meta) { this.log('http', msg, ...meta); }
  verbose(msg, ...meta) { this.log('verbose', msg, ...meta); }
  debug(msg, ...meta) { this.log('debug', msg, ...meta); }
  silly(msg, ...meta) { this.log('silly', msg, ...meta); }
}

// Used like this
this.wlogger = new LoggerWrap(logger); // Use the winston logger instance or console for testing
this.multibar.on('update-pre', this.wlogger.getCallback());

But there are still some open problems (probably not related to this):

• There is nothing printed to the console (not even the progress bar) until the end where everything is printed at once
• The progress bar seems to stop the script from terminating. The duration ticks up every second, but the script should be finished. Not sure what's going on there.

I'll post my final solution, when I got everything working.

[AndiDittrich]

• redraw-pre should be used (relative cursor reset applied - https://github.com/npkgz/cli-progress/blob/master/lib/multi-bar.js#L114).
• you have to stop the bar after your task has been finished (or use stopOnComplete) otherwise the timers will keep the application active

[Darkproduct]

I can't really solve this. I created an MWE, so anyone can reproduce this:

MWE

The only dependencies are winston and cli-progress.

import winston from 'winston';
import cliProgress from 'cli-progress';

/**
 * Create logger instance
 */
const logger = winston.createLogger({
  transports: [    
    // Console logging
    new winston.transports.Console({
      format: winston.format.combine(
        winston.format.splat(),
        winston.format.colorize(),
        winston.format.simple()
      ),
      colorize: true,
      level: 'silly'
    })
  ]
});

class LoggerWrap {
  /**
   * A wrapper for any logger with a `log` method to work with cli-progress
   * 
   * Compatible to:
   *  - `console`
   *  - `watson.Logger`
   * 
   * @param {watson.Logger|console} logger the logger instance
   */
  constructor(logger) {
    this.logger = logger;

    this.logArgs = new Array();
  }

  getCallback() {
    return () => {
      while (this.logArgs.length > 0) {
        const msg = this.logArgs.shift();
        this.logger.log(...msg);
      }
    };
  }

  // logger overrides
  log(...args) {
    // copy all values, to log them later and still log the current state
    this.logArgs.push(JSON.parse(JSON.stringify(args)));
  }

  // winston overrides
  error(msg, ...meta) { this.log('error', msg, ...meta); }
  warn(msg, ...meta) { this.log('warn', msg, ...meta); }
  info(msg, ...meta) { this.log('info', msg, ...meta); }
  http(msg, ...meta) { this.log('http', msg, ...meta); }
  verbose(msg, ...meta) { this.log('verbose', msg, ...meta); }
  debug(msg, ...meta) { this.log('debug', msg, ...meta); }
  silly(msg, ...meta) { this.log('silly', msg, ...meta); }
}

// First Test
logger.info('Start')

// Create wlogger and bar
const wlogger = new LoggerWrap(logger);
const bar = new cliProgress.SingleBar({
  clearOnComplete: true, // this would be true in production
  hideCursor: false,
});
bar.on('redraw-pre', wlogger.getCallback());

// create concurrent que
const request = (task) => new Promise((res, rej) => {
  wlogger.info('requesting %s', task);
  setTimeout(() => {
    if (Math.random() < 0.5) {
      wlogger.info('resolving %s', task);
      res(task);
    } else {
      wlogger.warn('rejecting %s', task);
      rej(task);
    }
  }, 1000 + Math.random() * 1000);
});

// Task list
const tasks = [1, 2, 3, 4, 5, 6];

// List of callables
const makeRequests = tasks.map(task => () => request(task));

const recurse = () => {
  const makeRequest = makeRequests.shift();
  return !makeRequest ? null : Promise.allSettled([makeRequest()])
    .then(() => {
      bar.increment();
      return recurse();
    })
};

bar.start(6);
const limit = 2;
await Promise.all(Array.from({ length: limit }, recurse))
  .then(() => {
    // The bar has to be stopped manually if not all of them finish
    bar.stop();

    // Handle logging que
    logger.debug('Print backlog:');
    wlogger.getCallback()();

    logger.info("Finished");
  });

// End Test
logger.info('End')

Output

$ node test.js
info: Start
progress [----------------------------------------] 0% | ETA: 0s | 0/6info: requesting 1
info: requesting 2
warn: rejecting 1
progress [=======---------------------------------] 16% | ETA: 8s | 1/6info: requesting 3
warn: rejecting 2
info: requesting 4
progress [=============---------------------------] 33% | ETA: 4s | 2/6info: resolving 3
progress [====================--------------------] 50% | ETA: 3s | 3/6info: requesting 5
info: resolving 4
info: requesting 6
progress [===========================-------------] 66% | ETA: 2s | 4/6warn: rejecting 6
progress [=================================-------] 83% | ETA: 1s | 5/6info: resolving 5
debug: Print backlog:
info: Finished
info: End

Discussion

• With clearOnComplete: true the last bar will be deleted properly.
• It looks like the "old" progress bar isn't deleted and the curser isn't reset to the start before the redraw-pre event is fired.

I know this is not an optimal solution, because the timestamps in winston won't be accurate.

[Darkproduct]

Ok, I found the issue. redraw-pre is emitted before the cursor is reset.

cli-progress/lib/generic-bar.js

Lines 86 to 107 in 0457e84

	if (forceRedraw || this.lastDrawnString != s){
	// trigger event
	this.emit('redraw-pre');
	// set cursor to start of line
	this.terminal.cursorTo(0, null);
	// write output
	this.terminal.write(s);
	// clear to the right from cursor
	this.terminal.clearRight();
	// store string
	this.lastDrawnString = s;
	// set last redraw time
	this.lastRedraw = Date.now();
	// trigger event
	this.emit('redraw-post');
	}

For better performance the line is never deleted as well, so moving the event down, wouldn't do much. I can fix my problems by adding: process.stderr.clearLine(-1); process.stderr.cursorTo(0, null); to the LoggerWrap.callback but I think that wouldn't be a nice solution. There should only be one process messing with the terminal commands at a time and that's cli-progress in this case.

My preferred solution would be a callback method, that if set, is called after resetting the curser and deleting the current line. Then the line would still only be deleted if this feature is needed.

[AndiDittrich]

the events of the generic bar are not exposed to the multibar instance and won't be populated outside
there are two different event implementations used for the single and multibar use-case. the logging functionality mentioned within other issues are only valid for multibar instances.

[Darkproduct]

Ok, then I would suggest making a uniform system, so there is no need for second documentation. Or name the events differently. For my MWE I thought a single-bar will be simpler than a multi-bar.

I changed my test code to:

import winston from 'winston';
import cliProgress from 'cli-progress';

/**
 * Create logger instance
 */
const logger = winston.createLogger({
  transports: [    
    // Console logging
    new winston.transports.Console({
      format: winston.format.combine(
        winston.format.splat(),
        winston.format.colorize(),
        winston.format.simple()
      ),
      colorize: true,
      level: 'silly'
    })
  ]
});

class LoggerWrap {
  /**
   * A wrapper for any logger with a `log` method to work with cli-progress
   * 
   * Compatible to:
   *  - `console`
   *  - `watson.Logger`
   * 
   * @param {watson.Logger|console} logger the logger instance
   */
  constructor(logger) {
    this.logger = logger;

    this.logArgs = new Array();
  }

  getCallback() {
    return () => {
      process.stderr.clearLine(-1);
      process.stderr.cursorTo(0, null);
      while (this.logArgs.length > 0) {
        const msg = this.logArgs.shift();
        this.logger.log(...msg);
      }
    };
  }

  // logger overrides
  log(...args) {
    // copy all values, to log them later and still log the current state
    this.logArgs.push(JSON.parse(JSON.stringify(args)));
  }

  // winston overrides
  error(msg, ...meta) { this.log('error', msg, ...meta); }
  warn(msg, ...meta) { this.log('warn', msg, ...meta); }
  info(msg, ...meta) { this.log('info', msg, ...meta); }
  http(msg, ...meta) { this.log('http', msg, ...meta); }
  verbose(msg, ...meta) { this.log('verbose', msg, ...meta); }
  debug(msg, ...meta) { this.log('debug', msg, ...meta); }
  silly(msg, ...meta) { this.log('silly', msg, ...meta); }
}

// First Test
logger.info('Start')

// Create wlogger and bar
const wlogger = new LoggerWrap(logger);

// Single Bar
// const bar = new cliProgress.SingleBar({
//   clearOnComplete: true, // this would be true in production
//   hideCursor: false,
// });
// bar.on('redraw-pre', wlogger.getCallback());
// bar.start(6);

// Multi Bar
const mbar = new cliProgress.MultiBar({
  clearOnComplete: true, // this would be true in production
  hideCursor: false,
});
mbar.on('redraw-pre', wlogger.getCallback());
const bar = mbar.create(6, 0);

// create concurrent que
const request = (task) => new Promise((res, rej) => {
  wlogger.info('requesting %s', task);
  setTimeout(() => {
    if (Math.random() < 0.5) {
      wlogger.info('resolving %s', task);
      res(task);
    } else {
      wlogger.warn('rejecting %s', task);
      rej(task);
    }
  }, 1000 + Math.random() * 1000);
});

// Task list
const tasks = [1, 2, 3, 4, 5, 6];

// List of callables
const makeRequests = tasks.map(task => () => request(task));

const recurse = () => {
  const makeRequest = makeRequests.shift();
  return !makeRequest ? null : Promise.allSettled([makeRequest()])
    .then(() => {
      bar.increment();
      return recurse();
    })
};

const limit = 2;
await Promise.all(Array.from({ length: limit }, recurse))
  .then(() => {
    // The bar has to be stopped manually if not all of them finish
    if (bar) bar.stop();
    if (mbar) mbar.stop();

    // Handle logging que
    logger.debug('Print backlog:');
    wlogger.getCallback()();

    logger.info("Finished");
  });

// End Test
logger.info('End')

And I get the following result:

$ node test.js
info: Start
info: requesting 1
info: requesting 2
info: resolving 1---------------------------------] 0% | ETA: 0s | 0/6
info: requesting 3
warn: rejecting 2---------------------------------] 16% | ETA: 7s | 1/6
info: requesting 4
warn: rejecting 4======---------------------------] 33% | ETA: 3s | 2/6
info: requesting 5
info: resolving 3=============--------------------] 50% | ETA: 3s | 3/6
info: requesting 6
info: resolving 5====================-------------] 66% | ETA: 2s | 4/6
debug: Print backlog:
warn: rejecting 6
info: Finished
info: End

It still looks like, that the line is not cleared before the event is fired. And that's the case:

cli-progress/lib/multi-bar.js

Lines 99 to 114 in 0457e84

	// internal update routine
	update(){
	// stop timer
	if (this.timer){
	clearTimeout(this.timer);
	this.timer = null;
	}
	// trigger event
	this.emit('update-pre');
	// reset cursor
	this.terminal.cursorRelativeReset();
	// trigger event
	this.emit('redraw-pre');

cli-progress/lib/terminal.js

Lines 72 to 86 in 0457e84

	// relative reset
	cursorRelativeReset(){
	if (!this.stream.isTTY){
	return;
	}
	// move cursor to initial line
	_readline.moveCursor(this.stream, 0, -this.dy);
	// first char
	_readline.cursorTo(this.stream, 0, null);
	// reset counter
	this.dy = 0;
	}

[AndiDittrich]

you have to clear it on your own..for performance reason only the end-of-line is cleared after the content have been updated.

atm i've absolutely no time for a refactoring of the codebase to allow logging functionality, sry

[Darkproduct]

Ok, that's fine.

Then here is my workaround code:
https://gist.github.com/Darkproduct/b12edf0b95db9f5554cff18e0f1d9581

Unfortunately, I had to set forceRedraw: true, because without this the bar was flickering too much because it is then only drawn when updated. It would be simple to fix if it is possible to check if an event listener is connected. Because then the line should be cleared beforehand and the bar redrawn afterward.

[Darkproduct]

https://nodejs.org/api/events.html#emitterlistenercounteventname
Should be suitable.

Should I submit a quick PR?

[AndiDittrich]

keep it as it is... i didn't have the time to check all possible implications - there are also other use-cases for the listener and such behaviour might break other users code..

maybe there will a a dedicated logging option in the future

[rhyy]

been using cli-progress for a few days now and at some point, i really need to log while the progress are running.

somehow this worked on my end. using redraw-pre and multiBar.terminal.clearLine():

import { MultiBar } from 'cli-progress'

const multiBar = new MultiBar({
  hideCursor: true,
  format: '{name} {bar} {percentage}%',
  barCompleteChar: '\u2588',
  barIncompleteChar: '\u2591',
  stopOnComplete: true,
  clearOnComplete: true
})

// create / update
for (let i = 1; i <= 5; i++) {
  let timer, progress = 0

  const bar = multiBar.create(1000, 0, {
    name: 'Bar #' + i
  }).on('stop', () => {
    clearInterval(timer)
    multiBar.remove(bar)            // fixes invisible bars
  })

  timer = setInterval(() => {
    bar.update(progress += 2 * i)
  }, 40)
}

// logging
!(function log(message = 'Logs below:') {
  if (!multiBar.isActive) return

  multiBar.once('redraw-pre', () => {
    multiBar.terminal.clearLine()   // <--
    console.log(message)            // log anything
  })

  setTimeout(() => log(new Date()), 1000)
})()