Building a logger with Undercut

In this tutorial we will use Undercut to build a non-complicated logger. The simplest one you can think of is just a console.log(), but we need more:

• Ability to disable logging where not needed without commenting out lines.
• Severity levels support with logger outputting only severe enough entries.
• Log entries processing and transformation (like middlewares).
• Support for custom destinations and outputting into other loggers.
• Less code.

Let's start with use case example:

function myAction(userId, postId) {
  // code
  log.info(() => `User ${userId} requesting post ${postId}`);
  // code
  log.debug(() => [`Current DB context is`, { dbContext }]);
  // code
}

Severity levels are embedded into method names, and we use Arrow Functions for building messages (and template literals instead of formatted strings for simplicity). If we need to pass some context among the message, we could do this as a Tuple (an array).

Of course, we want to have more data than just a message. A log entry should be more robust and could be an object with various meaningful properties:

{
  severity: 3,
  level: 'debug',
  timestamp: '2020-07-23T13:56:19.325Z',
  message: 'Current DB context is',
  context: { },
}

Such object could be processed by middlewares, which may add more information to it, format some values, filter excess entries, etc. Basic process may look like this:

[log_entry] => [middleware_1] => [middleware_2] => ... => [done]

A middleware could also output an entry somewhere as Browser's console or a remote web server. It should be configurable too.

As we're going to utilize Undercut for this task, let's think what would be the best choice for our requirements. Log entries come with time. If we can't iterate synchronously, the best option would be to use Observers (Push Lines).

After slight modifications the diagram from above may look like this:

[log_entry] => [------------- push_line--------------]
               [operation_1] => [operation_2] => ... ]

Before codding the Logger itself, we need to define severity levels:

// level.js

export const ERROR = 0;
export const WARNING = 1;
export const INFO = 2;
export const DEBUG = 3;

We will use a factory function approach for the Logger. Start with options:

// logger.js_1

import { filter, pushLine, toNull } from "@undercut/push";
import { isString } from "@undercut/utils";

import * as Level from "./level.js";

export function createLogger(pipeline, options = {}) {
  const isEnabled = options.isEnabled ?? true;
  const lowestSeverity = options.severity ?? Level.INFO;

The function requires a pipeline (a list of operations-middlewares) and an options object. isEnabled allows disabling logger entirely, level defines lowest allowed severity level (all levels lower will be skipped).

  const isAllowed = severity => severity <= lowestSeverity && isEnabled;
  const observer = pushLine(pipeline, toNull());

The observer will represent a chain of middlewares. We're using toNull target because there can be more than 1 destination to write logs and users will specify destinations within the pipeline, so toNull is just a placeholder.

  function log(severity, messageFactory) {
    if (!isAllowed(severity)) return;

    const timestamp = Date.now();
    const message = messageFactory();
    const entry = isString(message)
      ? { severity, timestamp, message }
      : { severity, timestamp, message: message[0], context: message[1] };

    observer.next(entry);
  }

The log function represents the whole logic of the Logger. Firstly we need to check severity level as soon as possible to lower performance penalty. Then we call the messageFactory (an arrow function where you specify the message) and look if it returns a tuple of [message, context] or just a message string. These values represent initial log entry, which we pass to the observer.

  return {
    error: m => log(Level.ERROR, m),
    warning: m => log(Level.WARNING, m),
    info: m => log(Level.INFO, m),
    debug: m => log(Level.DEBUG, m),
    observer: filter(e => isAllowed(e.severity))(observer)
  };
}

The logger object has methods for each severity level. This could be done automatically with a helper like collectProps and going through the Level enumeration, but manual way is the simplest one to get type ahead in IDEs.

Notice the observer property. It could be used by a middleware to pass entries from one logger to another. The observer is wrapped into a filter with severity level check. This check is done only in the log function for performance, so we need to add it here too.

The Logger is finished, but we need to provide a built-in middleware for connecting loggers together.

Every middleware is just a Push Operation. Knowing this and we could reuse operations from Undercut instead of writing our own from scratch.

import { filter, forEach, map } from "@undercut/push";

export function toLogger({ observer }) {
  return forEach(entry => observer.next(entry));
}

All toLogger does is getting that observer from a logger logger and passing all incoming log entries to it.

Let's add more middlewares.

export const convertTimestampToISO = map(entry => ({
  ...entry,
  timestamp: new Date(entry.timestamp).toISOString()
}));

convertTimestampToISO maps incoming log entry to a new object (a clone) with timestamp set to an ISO string instead of original Unix Time number.

export const filterNoContext = filter(entry => entry.context);

filterNoContext is even more simple and filters log entries with no context property.

export const toConsole = prefix =>
  forEach(entry => console.log(prefix + JSON.stringify(entry)));

toConsole outputs every log entry as a JSON string to browser's console adding text prefix at the beginning.

Testing time:

import * as Level from "./level.js";
import { createLogger, toLogger } from "./logger.js";
import {
  addLevelName,
  addProps,
  convertTimestampToISO,
  filterNoContext,
  toConsole,
  uppercaseMessage
} from "./middlewares.js";

const logger1 = createLogger(
  [
    convertTimestampToISO,
    addLevelName,
    addProps({ test: true }),
    toConsole("logger1: ")
  ],
  { severity: Level.WARNING }
);

logger1 processes only log entries with levels WARNING and ERROR. Processing of entries looks like this:

1. Create base entry { severity, timestamp, message, context }.
2. Convert timestamp to ISO string.
3. Add level prop.
4. Add test prop with value true.
5. Output entry to the console prefixed by "logger1: ".

We could create another logger and connect it to the prevoius:

const logger2 = createLogger(
  [
    filterNoContext,
    toLogger(logger1),
    uppercaseMessage,
    toConsole("logger2: ")
  ],
  { severity: Level.INFO }
);

logger2 processes severity levels INFO, WARN, ERROR, only DEBUG will be skipped.

1. Create base entry { severity, timestamp, message, context }.
2. Filter out entry without contexxt.
3. Pass entry to logger1.
4. Make message prop uppercase.
5. Output entry to the console prefixed by "logger2: ".

Now we can log some stuff:

const context = { username: "root" };
let counter = 100;

logger1.debug(() => `Debug message: ${counter++}`);
// No output from logger1 because of low severity.

logger1.info(() => `Info message: ${counter++}`);
// No output from logger1 because of low severity.

logger1.warning(() => `Warning message: ${counter++}`);
// logger1: {"severity":1,"timestamp":"2020-07-24T12:34:58.894Z","message":"Warning message: 100","level":"warning","test":true}

logger1.error(() => `Error message: ${counter++}`);
// logger1: {"severity":0,"timestamp":"2020-07-24T12:34:58.895Z","message":"Error message: 101","level":"error","test":true}

logger2.info(() => [`Info message: ${counter++}`, context]);
// No output from logger1 because of low severity.
// logger2: {"severity":2,"timestamp":1595594098895,"message":"INFO MESSAGE: 102","context":{"username":"root"}}

logger2.error(() => `Error message: ${counter++}`);
// No output from logger1 because was filtered by logger2.
// No output from logger2 because of missing context.

logger2.error(() => [`Error message: ${counter++}`, context]);
// logger1: {"severity":0,"timestamp":"2020-07-24T12:34:58.895Z","message":"Error message: 104","context":{"username":"root"},"level":"error","test":true}
// logger2: {"severity":0,"timestamp":1595594098895,"message":"ERROR MESSAGE: 104","context":{"username":"root"}}

That's it. Try yourself to make some cool middlewares or use the knowledge in other projects. Feel free to ask your questions in comments.

Visit GitHub Undercut repository for code and undercut.js.org website for documentation.

Photo by NeONBRAND on Unsplash