Winston: Throttle Logs

[Sicria]

Is it possible to throttle duplicate logs from sending to third-party transports?

I have a pushover transport which logs all critical logs but if I have an error which occurs more than once a second, it begins to flood the logger and if not stopped/prevented it could end up costing a lot of money.

Looking to be able to hash the contents of the message and prevent sending if the hash is within a given timeframe. This would prevent overcharges in services which charge in volume.

[dutu]

@Sicria, code below is excerpt from something I'm using (I'm sure it can be adapted to your own needs)

import winston from 'winston'
import _ from 'lodash'

class LimiterTransport extends winston.Transport {
  constructor(options) {
    super(options)
    this.level = options && options.level || 'info'
    this.lastLogs = []

    this.consoleLogger = new (winston.Logger)({
      transports: [
        new (winston.transports.Console)(options),
      ]
    });
  }

  log(level, msg, meta, callback) {
    let lcl = meta && meta.lcl || null
    let llim = meta && meta.llim || 0
    if (!lcl || llim === 0) {
      this.consoleLogger[level](msg)
    } else {
      let newLog = {
        lcl: lcl,
        at: Date.now(),
      }

      let lastLogIndex = _.findIndex(this.lastLogs, { lcl: lcl})
      if (lastLogIndex === -1 || newLog.at > this.lastLogs[lastLogIndex].at + llim * 1000) {
        delete meta.lcl
        delete meta.llim
        this.consoleLogger[level](msg)
        if (lastLogIndex === -1) {
          this.lastLogs.push(newLog)
        } else {
          this.lastLogs.splice(lastLogIndex, 1, newLog)
        }
      }
    }

    callback(null, true)
  }
}

winston.transports.LimiterTransport = LimiterTransport;

let log = new winston.Logger({
  transports: [
    new (winston.transports.LimiterTransport)(),
  ],
});

while (true)  {
  log.info('Log this maximum once every 10 seconds', { lcl: 'a log class', llim: 10 });
  log.info('Log this maximum once every 15 seconds', { lcl: 'another log class', llim: 15 });
}

In addition to your string, you'd need to pass { lcl: String, llim: Number }
( lcl is 'log class' and llim is 'log limit')

Discards (do not output) logs with the same lcl which are logged within llim interval in seconds.

Hope it helps

EDIT: you can still use log('something') (without the last object), in which case it logs everything as normal (without any limitation)

[Sicria]

@dutu Thanks for the great starting point. I've modified your code to work with my implementation a bit nicer. I've used a hash of the message and meta to give the log an identifier. It's not the cleanest code and if your transport you want to throttle has an option of timeout or Transport you might have some trouble. (I guess you could prefix them to avoid clashes).

import { Transport } from 'winston';
import { get, set } from 'lodash';
import hash from 'object-hash';

export default class ThrottleTransport extends Transport {
  constructor(options) {
    super(options);

    const transportOptions = { ...options };
    delete transportOptions.Transport;
    delete transportOptions.timeout;

    this.timeout = options.timeout || 15000;
    this.lastLogs = {};
    this.logger = new (options.Transport)(transportOptions);
  }

  log(level, msg, meta, callback) {
    const logHash = hash({ msg, meta });
    const now = Date.now();
    const previousLog = get(this.lastLogs, logHash, null);

    // Check if there's no previous log, or if the previous log has since timed out
    if (!previousLog || now > (previousLog + this.timeout)) {
      // Add the log meta to the previous logs
      set(this.lastLogs, logHash, now);

      // Forward the log to the logger
      this.logger.log(level, msg, meta, callback);
      return;
    }

    return callback(null, true);
  }
}

logger.add(ThrottleTransport, {
  Transport: winston.transports.Console,
  level: 'debug',
  handleExceptions: true,
  humanReadableUnhandledException: true,
  json: false,
  colorize: true,
  prettyPrint: true,
});

This code will have the same problem which yours has where as there's new logs, the internal store of logs will keep growing, which could cause an issue if it gets too large. You could purge old logs which have since timed out to avoid this.

I've not tested this in production so use at your own risk. _Could have weird side effects_

[dutu]

@Sicria , thanks for the feedback. Would you please elaborate on 'the internal store of logs will keep growing, which could cause an issue if it gets too large'

I don't immediately see the issue. I notice that this.lastLogs can grow, but it'll only be when logs with different logHash (or lcl in my case) are received.

I'd appreciate if you can give additional clarification on your statement.
Thank you

[Sicria]

It will just keep growing, the only way it will be empty is if the app restarts.

In my case of using hashes and throttling every message which comes to that transport, it could become large quick, depending on how many unique logs I'm sending to it.

In your case, it really depends on how many unique logs you have which you're manually throttling with lcl. If you're only throttling a handful of logs, then you won't have much of an issue.

I could add a setTimeout to the constructor of my method which periodically purges old logs from the local store, that would probably solve this issue. But then you've got the other issue of a function being called over and over, even if you've not sent any logs to it.

[dutu]

Yeah, using hashes on entire message and meta makes the issue worse.
You could literary have an infinity of unique messages (for example if current timestamp is included in the message)
You could purge the old logs when a log is processed, rather than at a set interval (possibly combined with a timeout not to slow down the app too much)

[Sicria]

You're right about hashing the message & the meta as if it contains a timestamp it wouldn't ever really throttle the log.

I've changed the way the logHash is created, instead of using the msg & meta it now hashes the call stack of the log. That way each log within the app _should_ always have a unique identifier. This removes any risk of logs containing timestamps which might mess up the throttling.

import callsite from 'callsite';

static getLogId() {
  const stack = [];
  // Get the current call stack and convert it to the array
  callsite().forEach((site) => {
    if (!site || typeof site.toString !== 'function') return;
    stack.push(site.toString());
  });

  // Hash the stack to create a unique identifier for the log
  return hash(stack);
}

Ended up adding this code to the log method to just cleanup any old logs which may be called infrequently, no sense keeping a reference to them anymore.

this.lastLogs = Object.entries(this.lastLogs).reduce((logs, [key, value]) => {
  // Remove the log if it has timed out
  if (now > (value + this.timeout)) return logs;
  // Return the log as it's still valid
  return { ...logs, [key]: value };
}, {});

[dutu]

Interesting idea, thanks!

BTW, I'd still prefer to have the timeout passed as parameter with each log (rather than in the constructor). This way you can use the same logger for normal logging and have throttling only when needed (and with different timeout value). Anyway, it's just a matter of needs/taste

Thanks for the convo. Instructive :)

[indexzero]

Great to see efforts like this evolve in the ecosystem of the project. Going to put the "faq" label on this because throttling seems like a technique other folks would be interested in. Maybe consider releasing the ThrottleTransport as a standalone module!

[Kubessandra]

I just published the transport on npm,
Ping me so I can add you as collaborators, if you want to.

I made some changes:

• Fixed the memory leak with the logHash, now the key is deleted when the timeout is reached.
• Updated it to the winston-transport package.

We are using it in production right now, but the package need more time to be well tested.
winston-limit-transport