How can I override console.log such that each call has a UUID of an object?

Question

I am writing a class in Node.js which completes a series of web requests. This class is instantiated multiple times to perform different web requests. The program is executed in the terminal, and thus I need specific logging capabilities so that I can debug errors and observe success.

I have overridden the function definitions for each so that I can prepend a UUID to each log statement like so:

[16:07:22.911] [LOG]    [54fccbc5-f6c8-4e0a-b42a-196e831df0e6]  hello from worker 1

In this case, each UUID is unique to the instance of the class.

I use another npm module, console-stamp to add the timestamp and log-level metadata.

require('console-stamp')(console, {
  pattern: 'HH:MM:ss.l',
  colors: {
    stamp: chalk.cyan,
  },
});

To do this override, I created a method which attaches the UUID of the worker class to log statements:

function addUuidToConsole(uuid) {
  if (console.log) {
    const old = console.log;
    console.log = function log(...args) {
      Array.prototype.unshift.call(args, `[${uuid}] `);
      old.apply(this, args);
    };
  }
  if (console.warn) {
    const old = console.warn;
    console.warn = function warn(...args) {
      Array.prototype.unshift.call(args, `[${chalk.red(uuid)}] `);
      old.apply(this, args);
    };
  }
  if (console.error) {
    const old = console.error;
    console.error = function error(...args) {
      Array.prototype.unshift.call(args, `[${chalk.red(uuid)}] `);
      old.apply(this, args);
    };
  }
}

Then in my constructor of the my class, I call this function with the uuid of the instance.

class Worker {
  constructor(profile) {
    ...
    this.uuid = uuidv4();
    ...
    addUuidToConsole(this.uuid);
    ...
  }
  ...
}

Problem

This solution is satisfactory for when I only use one instance of Worker. However when I use more than 1 instance, the subsequent UUIDs are prepended sequentially.

[16:45:47.606] [LOG]    [9ce5e2b8-d49d-40c9-bb9d-3ed9e83fb441]  hello from worker 1
[16:45:47.607] [LOG]    [9ce5e2b8-d49d-40c9-bb9d-3ed9e83fb441]  [ef5bab6c-31c2-4ad9-aea0-c435f1861989]  hello from worker 2

Furthermore, my secondary problem is that this overriding throws off my use of console.time() and console.timeEnd() which I use to measure the efficacy of my requests.

I use the UUID when calling these timing methods and after overriding this has gotten very ugly. When I call console.timeEnd(), I receive an output like so:

[16:45:47.606] [LOG]    [9ce5e2b8-d49d-40c9-bb9d-3ed9e83fb441]  %s: %sms 9ce5e2b8-d49d-40c9-bb9d-3ed9e83fb441 3.860

What I want of course is for the logs to be visibly separate and not "cumulative". I think this error is because the Worker instances share the same console object, although I'm not sure how I can get around this so so that their outputs resemble:

[16:45:47.606] [LOG]    [9ce5e2b8-d49d-40c9-bb9d-3ed9e83fb441]  hello from worker 1
[16:45:47.607] [LOG]    [ef5bab6c-31c2-4ad9-aea0-c435f1861989]  hello from worker 2

One solution I considered would be to discard my overridden methods and use a formatMessage() function inside of each of my calls to console.log() and console.debug() and so forth.

My question is how can I design an elegant solution so that I can quickly distinguish log output from different Worker instances. I appreciate your suggestions and input.

Answer 1

Your problem is that console is a singleton object. Each call to addUuidToConsole wraps the previous version of the log/warn/error function in a [yet another] function that prepends a UUID.

What you want is a distinct log object for each of your workers, none of which actually modify the console global object. Instead, each object should provide a console-like API that modifies any arguments passed to it as needed, before forwarding them to the corresponding console method. As it turns out, this is a great use case for the Proxy class.

For example:

/**
 * Function to create a console-like object that prefixes
 * any (well, okay, most) output with "[${tag}]".
 *
 * This will behave identical to the built-in `console`, except
 * where provide custom wrapper functions, below.
 *
 * @param {String} prefix string
 */
function taggedConsole(tag) {
  // Cache of wrapper functions
  const wraps = {};

  // Return a Proxy for the console object
  return new Proxy(console, {
    // Trap for when `console[prop]` is referenced
    get(target, prop) {
      // If we've already created a wrapper function, return it
      if (wraps[prop]) return wraps[prop];

      // Functions we wrap (to inject `[tag]` argument)
      switch (prop) {
        // Create a wrapper to insert `tag` as the first arg
        case "debug":
        case "log":
        case "info":
        case "warn":
        case "error":
          wraps[prop] = function(...args) {
            return console[prop](`[${tag}]`, ...args);
          };
          break;

        // Create a wrapper to prefix the first arg with `tag`
        case "count":
        case "countReset":
        case "group":    // Note: Takes a label arg, but 
        case "groupEnd": // groupEnd ignores label arg so... :-/
        case "time":
        case "timeEnd":
        case "timeLog":
        case "trace":
          wraps[prop] = function(...args) {
            args[0] = `[${tag}] ${args[0]}`;
            return console[prop](...args);
          };
          break;
      }

      // Return wrapper if defined, otherwise return the original function
      return wraps[prop] || target[prop];
    }
  });
}

// FOR EXAMPLE ...

// Create a couple example consoles
consoleFoo = taggedConsole("FOO");
consoleBar = taggedConsole("BAR");

// Log stuff (output prefixed with the tag)
consoleFoo.log("hello");
consoleBar.log("world");

// Other functions that provide tag as prefix
consoleFoo.time("fdsafd");
consoleFoo.timeEnd("fdsafd");
consoleFoo.trace("fdsafd");