Creating a TypeScript Logger Facade

Table of Contents

TLDR

😎 The code below can be reviewed, forked, and interacted with via this StackBlitz project:

https://stackblitz.com/edit/typescript-qmooji?devToolsHeight=33&file=index.ts

Why Use a Logger Facade?

A logger facade defines a common interface for logging. Benefits of a common interface for logging include:

1. Ensure logs are captured in a consistent manner.
2. Easily capture and augment relevant details so that troubleshooting and analysis can be performed quickly.
3. Provide an abstraction over the logging implementation so that it can be swapped out. In the JavaScript ecosystem, this is particularly helpful since many logging libraries designed for NodeJs do not work in a web browser runtime environment. The facade may be more easily mocked for automated testing against logging.

Limitations of console.log()

The NodeJs Console actually has some nice features, but it differs in implementation and features as compared to the web browser. If you are working in a full JavaScript stack, this can result in confusion and error. It would be great if JavaScript runtimes could settle on a normalized, built-in logging module, similar to what is offered in .NET Core and Python!

See also:

• https://learn.microsoft.com/en-us/aspnet/core/fundamentals/logging/?view=aspnetcore-8.0
• https://docs.python.org/3/howto/logging.html

Building the Logger Facade

In the iterations below, we define and implement common logger features.

😎 The code below can be reviewed, forked, and interacted with via this StackBlitz project:

https://stackblitz.com/edit/typescript-qmooji?devToolsHeight=33&file=index.ts

Iteration 1: Named Loggers, Log Levels, and Logging Strings

1. Named Loggers: As a developer, I want to get a logger by providing a string-based name so that I can associate log entries to an appropriate scope such as file/module, class, or function.
2. Log Levels: As a developer, I want to categorize log entries with the levels of trace, debug, info, warn, and error, so that I can:
   • avoid performance concerns by rendering only the necessary logs
   • easily filter on log level when searching through logs
   • react to leg entries of a certain level, for example, by sending an email alert when errors are logged
   • at runtime, specify a log level and have only that level and higher be rendered to output.
3. As a developer, I want to log a string that labels and/or adds context to the log entry

index.ts

/**
 * logger-facade visual tests
 */

import { LoggerFacade, LogLevel } from './logger-facade';
import {
  StructuredConsoleProvider,
  StructuredConsoleProviderConfig,
} from './logger-structured-console';

scenario('StructuredConsoleProvider w/ default config', {});

scenario('StructuredConsoleProvider w/ WARN log level', {
  level: 'WARN',
});

function scenario(
  description: string,
  config: StructuredConsoleProviderConfig
) {
  console.log(`SCENARIO: ${description}`);

  LoggerFacade.configure(new StructuredConsoleProvider(config));

  const logger = LoggerFacade.getLogger('scenario');

  for (let level of Object.keys(LogLevel)) {
    logger.log({
      level: level as LogLevel,
      message: `${level}-test-1`,
    });
  }
}

logger-facade.ts

/**
 * Allowed log levels
 */
export const LogLevel = {
  TRACE: 'TRACE',
  DEBUG: 'DEBUG',
  INFO: 'INFO',
  WARN: 'WARN',
  ERROR: 'ERROR',
} as const;

/**
 * Log Level type
 */
export type LogLevel = typeof LogLevel[keyof typeof LogLevel];

// NOTE: the above solution utilizes a type-safe technique
// that is flexible and avoids some common issues and concerns
// with TypeScript enum types.

export type LogEntry = {
  level: LogLevel;
  message: string;
};

export type FacadeLogger = {
  log(entry: LogEntry): void;
};

export type LoggerFacadeProvider = {
  getLogger(name: string): FacadeLogger;
};

export class LoggerFacadeProviderNotConfigured extends Error {
  constructor() {
    super(
      'LoggerFacadeProvider is not configured. Call LoggerFacade.configure() first'
    );
  }
}

export class LoggerFacade {
  private static provider: LoggerFacadeProvider | null = null;

  public static configure(provider: LoggerFacadeProvider) {
    LoggerFacade.provider = provider;
    LoggerFacade.getLogger = LoggerFacade.provider.getLogger.bind(
      LoggerFacade.provider
    );
  }

  public static getLogger(_name: string): FacadeLogger {
    // stub out getLogger
    throw new LoggerFacadeProviderNotConfigured();
  }
}

logger-structured-console.ts

import {
  FacadeLogger,
  LogEntry,
  LoggerFacadeProvider,
  LogLevel,
} from './logger-facade';

/**
 * Mapping of level values for "> LOG_LEVEL" filtering
 */
const levelValues = new Map<LogLevel, number>([
  ['TRACE', 0],
  ['DEBUG', 1],
  ['INFO', 2],
  ['WARN', 3],
  ['ERROR', 4],
]);

const DEFAULT_LEVEL: LogLevel = 'INFO';
const DEFAULT_LEVEL_VALUE = 2;

type StructuredConsoleLoggerInput = {
  config?: StructuredConsoleProviderConfig;
  name: string;
};

class StructuredConsoleLogger implements FacadeLogger {
  private readonly targetLevel: LogLevel;
  private readonly targetLevelValue: number;

  constructor(private input: StructuredConsoleLoggerInput) {
    this.targetLevel = this.input?.config?.level ?? DEFAULT_LEVEL;
    this.targetLevelValue =
      levelValues.get(this.targetLevel) ?? DEFAULT_LEVEL_VALUE;
  }

  log(entry: LogEntry): void {
    const entryLevelValue = levelValues.get(entry.level) ?? DEFAULT_LEVEL_VALUE;
    if (entryLevelValue < this.targetLevelValue) {
      return;
    }

    console.log(JSON.stringify(entry));
  }
}

export type StructuredConsoleProviderConfig = {
  /**
   * The minimal log level to output.
   * @default - 'INFO'
   */
  level?: LogLevel;
};

/**
 * An LoggerFacade implementation that
 * delegates to `global.console` and structures log output
 * with JSON
 *
 * @example
 *
 * // in app startup routine, add the following
 * LoggerFacade.configure(new StructuredConsoleProvider({
 *   // configuration options
 * }));
 *
 * // in application code, create and use a logger
 * class MyClass {
 *  private readonly logger = LoggerFacade.getLogger(MyClass.name);
 *
 *  foo() {
 *    this.logger.log({ level: 'INFO' , message: 'BEGIN: foo()' });
 *  }
 * }
 */
export class StructuredConsoleProvider implements LoggerFacadeProvider {
  constructor(
    private config: StructuredConsoleProviderConfig | undefined = undefined
  ) {}

  getLogger(name: string): FacadeLogger {
    const { config } = this;
    return new StructuredConsoleLogger({
      name,
      config,
    });
  }
}

Output and Review

SCENARIO: StructuredConsoleProvider w/ default config
{"level":"INFO","message":"INFO-test-1"}
{"level":"WARN","message":"WARN-test-1"}
{"level":"ERROR","message":"ERROR-test-1"}

SCENARIO: StructuredConsoleProvider w/ WARN log level
{"level":"WARN","message":"WARN-test-1"}
{"level":"ERROR","message":"ERROR-test-1"}

Not bad! We are well on the way to simplifying and standardizing logging.

The logging output is in JSON, which is commonly supported by log shipping services, such as Splunk and AWS CloudWatch. Structuring log data increases its query-ability in such services. For example, you can query for all errors in CloudWatch with a filter like this: { $.level="ERROR" }

In iteration 2, let’s make some small tweaks to improve DX.

Iteration 2: Timestamps and Shortcut Functions

1. As a developer, I want to include timestamps in logging output so that I can observe time taken on certain processes and provide “real” time to log shipping services such as Splunk or Cloudwatch.
2. As a developer, I want shortcut functions for logging at different levels so that I have to write less code.

Notable Changes

👇 Here are the notable changes. For full detail, refer to the Stackblitz Project

index.ts.scenario()

Use the shortcut methods. These will be used 99% of time vs the more verbose log() method.

  logger.trace('trace-test');
  logger.debug('debug-test');
  logger.info('info-test');
  logger.warn('warn-test');
  logger.error('error-test');

logger-facade.ts.FacadeLogger

Update the facade contract.

export type FacadeLogger = {
  log(entry: LogEntry): void;
  trace(message: string): void;
  debug(message: string): void;
  info(message: string): void;
  warn(message: string): void;
  error(message: string): void;
};

logger-structured-console.ts

Implement the shortcut methods.

  trace(message: string): void {
    this.log({ level: 'TRACE', message });
  }

  debug(message: string): void {
    this.log({ level: 'DEBUG', message });
  }

  info(message: string): void {
    this.log({ level: 'INFO', message });
  }

  warn(message: string): void {
    this.log({ level: 'WARN', message });
  }

  error(message: string): void {
    this.log({ level: 'ERROR', message });
  }

Extend the implementation to support logger customization and augmentation. Here, we have established a plugin system for formatting log output which is dog-fooded by StructuredConsoleLogger, and we’re following the Open/Closed principle of SOLID.

NOTE: Additional augmentation will be explored further down.

const levelValues = new Map<LogLevel, number>([
  ['TRACE', 0],
  ['DEBUG', 1],
  ['INFO', 2],
  ['WARN', 3],
  ['ERROR', 4],
]);

const DEFAULT_LEVEL: LogLevel = 'INFO';
const DEFAULT_LEVEL_VALUE = 2;

type StructuredConsoleLoggerFormatter = {
  format(entry: LogEntry): LogEntry;
};

export class TimestampFormatter implements StructuredConsoleLoggerFormatter {
  format(entry: LogEntry): LogEntry {
    return {
      time: new Date().toISOString(),
      ...entry,
    };
  }
}

export type StructuredConsoleProviderConfig = {
  /**
   * The minimal log level to output.
   * @default - 'INFO'
   */
  level?: LogLevel;

  /**
   * Augment logging structure
   * @default - {[TimestampFormatter]}
   */
  formatters?: StructuredConsoleLoggerFormatter[];
};

type StructuredConsoleLoggerInput = {
  config?: StructuredConsoleProviderConfig;
  name: string;
};

Output and Review

SCENARIO: StructuredConsoleProvider w/ default config
{"time":"2024-01-07T20:31:06.809Z","level":"INFO","message":"info-test"}
{"time":"2024-01-07T20:31:06.809Z","level":"WARN","message":"warn-test"}
{"time":"2024-01-07T20:31:06.809Z","level":"ERROR","message":"error-test"}

SCENARIO: StructuredConsoleProvider w/ WARN log level
{"time":"2024-01-07T20:31:06.809Z","level":"WARN","message":"warn-test"}
{"time":"2024-01-07T20:31:06.809Z","level":"ERROR","message":"error-test"}

Nice! A minimal logging statement now only requires logger.debug('my message') vs logger.log({ level: 'DEBUG', message: 'my message'}).

And, by default, a time stamp if included in universal ISO 8601 standard format.

Iteration 3: Additional Details

When something bad happens, logging is a first stop for troubleshooting. But, to be really useful, additional context is often needed in the log entry such as:

• id values: user id, user name, process id
• function arguments
• function output
• resulting errors

Do any of the following coding patterns look familiar?

function getUser(userId: string) {
    // Point A: Debug when this function is called
    // and what userId it is called with.
    logger.debug(`getUser( ${userId})`);
    try {
      const user = userService.getById(userId);
      // Point B: Debug the response of userService.
      // There are at least 2 concerns here
      //  1. The user data will not be structured.  As a result
      //     it is less query-able and helpful for impact analysis
      //  2. Depending on the size of the `user` object, this computation
      //     can have a major impact on API response times AND compute costs.
      //     The JSON.stringify() will be always be evaluated, even if
      //     the configured log level is higher than `DEBUG`
      logger.debug(`getUser( ${userId}) => ` + JSON.stringify(user));
      return user;
    } catch (err) {
      if (err instanceof Error) {
        // Point C: Log and rethrow the error with some details to help with troubleshooting
        logger.error('Failed to getUser' + JSON.stringify({err}));
        throw err;
      }
    }
  }

In a code review of the above snippet, what concerns might come up?

• Point A
  • performance: No concerns.
  • cost: No concerns, assuming log level is configured appropriately and not left
  • security: No concerns, assuming userId is not associated with with PII or is otherwise qualified as secret data.
  • other: The factor, userId, is embedded in the log message. As a result, its query-ability is reduced, making impact analysis more difficult.
• Point B
  • performance:
    • Depending on the size of the user object and the busy-ness of this code path, the JSON.stringify call can have a major impact on API response times, especially since JSON.stringify is always called, even if the configured log level is greater than DEBUG.
  • cost:
    • If log level is misconfigured, a busy API can easily cost $100s and $1000s per month for log shipping services.
    • The JSON.stringify perf concern can impact compute costs, requiring that you scale out and pay for more compute.
  • security: If user contains PII, such as email, it should either be obfuscated or removed from logging output.
  • other: Same as Point A. This technique results in unstructured log data.
• Point C
  • performance: Same as Point B. An Error object be very large. It often contains circular dependencies which JSON.stringify does not handle well.
  • cost: Same concerns as point B.
  • security: Again, make sure there’s no PII or protected data in here.
  • other: Handling all errors in this manner can result in duplicate logging. If this code is not going to handle the error, it is better to let the error bubble up to an ExceptionManager which is coded to handle various errors and/or apply different error handling strategies, such as “ignore” or “log and report”. Managing exceptions is worthy of its own article. Retry strategy is another consideration when dealing with async requests (Let me know if you have interest in these topics!)

So, what are going to address with this iteration?! 🤨

1. As a developer, I want to include structured detail in a log entry ad-hoc so that it is queryable.
2. As a developer, I want to be able to log errors so that I can ensure they are logged in a consistent, queryable format.
3. As a developer, I want to specify contextual data to be included in all log entries so that I do not have to remember to include it in related log entries and so that it can be associated with code and exceptions I do not own.
4. As a developer, I want to avoid expensive operations in logged when unnecessary so that my processes are responsive and incur no additional costs for logging.

Notable Changes

👇 Here are the notable changes. For full detail, refer to the Stackblitz Project

index.ts

Update the scenarios to include additional factors, including:

• an error
• a custom formatter that appends the current user id
• ad-hoc detail

class CustomError extends Error {
  constructor() {
    super('Well, that did not work');
  }
}

class UserIdFormatter implements StructuredConsoleLoggerFormatter {
  format(entry: LogEntry): LogEntry {
    return {
      ...entry,
      // In a real application, this would come from a Store
      // that keep track of the curret user ID
      userId: '0e7bc6b9-454b-490a-a506-b20906e0ef3a',
    };
  }
}

scenario('StructuredConsoleProvider w/ default config', {});

scenario('StructuredConsoleProvider w/ WARN log level', {
  level: 'WARN',
  formatters: [
    ...StructuredConsoleLogger.DefaultFormatters,
    new UserIdFormatter(),
  ],
});

function scenario(
  description: string,
  config: StructuredConsoleProviderConfig
) {
  console.log(`SCENARIO: ${description}`);

  LoggerFacade.configure(new StructuredConsoleProvider(config));

  const logger = LoggerFacade.getLogger('scenario');

  const detail = {
    someValue: 1,
    someFlag: true,
    someString: 'hello?',
    error: new CustomError(),
  };

  logger.trace('trace-test', detail);
  logger.debug('debug-test');
  logger.info('info-test');
  logger.warn('warn-test');
  logger.error('error-test', detail);
}

logger-facade.ts

Update the contract to allow additional details and DRY up typings a bit.

export type LogDetail =
  | string
  | number
  | boolean
  | Error
  | Record<string, unknown>;

export type LogDetails = Record<string, LogDetail>;

export type LogEntry = Record<string, LogDetail> & {
  level: LogLevel;
  message: string;
};

export type FacadeLoggerMethod = (message: string, detail?: LogDetails) => void;

export type FacadeLogger = {
  log(entry: LogEntry): void;
  trace: FacadeLoggerMethod;
  debug: FacadeLoggerMethod;
  info: FacadeLoggerMethod;
  warn: FacadeLoggerMethod;
  error: FacadeLoggerMethod;
};

logger-structured-console.ts

• Add ErrorFormatter
• Update and expose default formatters so that can be re-used in configuration.
• Implement detail argument.

  export class ErrorFormatter implements StructuredConsoleLoggerFormatter {
    format(entry: LogEntry): LogEntry {
      const next: LogEntry = { ...entry };

      for (let [key, value] of Object.entries(entry)) {
        if (value instanceof Error) {
          const error = {
            message: value.message,
            name: value.name,
            cause: value.cause,
            detail: value.toString(),
            stack: value.stack,
          };
          next[key] = error;
        } else {
          next[key] = value;
        }
      }

      return next;
    }
  }

  // ...

  export class StructuredConsoleLogger implements FacadeLogger {
  // ...
  public static DefaultFormatters = [
    new TimestampFormatter(),
    new ErrorFormatter(),
  ];

  // ...

  trace: FacadeLoggerMethod = (message, detail): void => {
    this.log({ level: 'TRACE', message, ...detail });
  };

Output and Review

SCENARIO: StructuredConsoleProvider w/ default config
{"time":"2024-01-07T22:30:52.738Z","level":"INFO","message":"info-test"}
{"time":"2024-01-07T22:30:52.738Z","level":"WARN","message":"warn-test"}
{"time":"2024-01-07T22:30:52.738Z","level":"ERROR","message":"error-test","someValue":1,"someFlag":true,"someString":"hello?","error":{"message":"Well, that did not work","name":"Error","detail":"Error: Well, that did not work","stack":"Error: Well, that did not work\n    at scenario (https://typescript-qmooji.stackblitz.io/~/index.ts:37:16)\n    at Object.eval (https://typescript-qmooji.stackblitz.io/~/index.ts:21:1)\n    at eval (https://typescript-qmooji.stackblitz.io/~/index.ts:49:4)\n    at eval (https://typescript-qmooji.stackblitz.io/~/index.ts:50:3)\n    at eval (<anonymous>)\n    at Qt (https://c.staticblitz.com/d/webcontainer.a8c70b9797689ab630bc39693935365c46b0aa9d.js:15:30145)\n    at https://c.staticblitz.com/d/webcontainer.a8c70b9797689ab630bc39693935365c46b0aa9d.js:15:38799\n    at U (https://c.staticblitz.com/d/webcontainer.a8c70b9797689ab630bc39693935365c46b0aa9d.js:15:13565)\n    at https://c.staticblitz.com/d/webcontainer.a8c70b9797689ab630bc39693935365c46b0aa9d.js:15:13207\n    at boot (https://typescript-qmooji.stackblitz.io/dev/boot:6:3)"}}

SCENARIO: StructuredConsoleProvider w/ WARN log level
{"time":"2024-01-07T22:30:52.738Z","level":"WARN","message":"warn-test","userId":"0e7bc6b9-454b-490a-a506-b20906e0ef3a"}
{"time":"2024-01-07T22:30:52.738Z","level":"ERROR","message":"error-test","someValue":1,"someFlag":true,"someString":"hello?","error":{"message":"Well, that did not work","name":"Error","detail":"Error: Well, that did not work","stack":"Error: Well, that did not work\n    at scenario (https://typescript-qmooji.stackblitz.io/~/index.ts:37:16)\n    at Object.eval (https://typescript-qmooji.stackblitz.io/~/index.ts:22:1)\n    at eval (https://typescript-qmooji.stackblitz.io/~/index.ts:49:4)\n    at eval (https://typescript-qmooji.stackblitz.io/~/index.ts:50:3)\n    at eval (<anonymous>)\n    at Qt (https://c.staticblitz.com/d/webcontainer.a8c70b9797689ab630bc39693935365c46b0aa9d.js:15:30145)\n    at https://c.staticblitz.com/d/webcontainer.a8c70b9797689ab630bc39693935365c46b0aa9d.js:15:38799\n    at U (https://c.staticblitz.com/d/webcontainer.a8c70b9797689ab630bc39693935365c46b0aa9d.js:15:13565)\n    at https://c.staticblitz.com/d/webcontainer.a8c70b9797689ab630bc39693935365c46b0aa9d.js:15:13207\n    at boot (https://typescript-qmooji.stackblitz.io/dev/boot:6:3)"},"userId":"0e7bc6b9-454b-490a-a506-b20906e0ef3a"}

Phew! Things are getting complicated now 😅.

If you examine StructuredConsoleLogger.log(), the perf issue has been partially addressed. JSON.stringify will not be called on any object unless the log entry matches the configured log level. You can certainly still shoot yourself in the foot by coding something like:

    // don't do this
    logger.debug('stuff', {
        myvalue: JSON.string(largeObject),
        otherValue : expensiveFn()
    });

Code reviews (and possibly linting) are still valuable!

The value of the current user id is automatically appended where applicable. Errors are output consistently. And ad-hoc detail/factors can be included for troubleshooting.

Alternative Solution

Instead of creating a new API for a logger facade, the global.console object could be modified and augmented to provide desired logging functionality.

Benefits:

• No additional logger facade API to maintain.
• May allow common configuration of 3rd party libraries that reference global.console. For example, in Python, you may want to turn down the log level for boto3 libraries (the Python aws sdk). You can do this using the standard logging library configuration vs a separate boto3 configuration

Caveats:

• The allowed arguments for debug, log, warn, error do not enforce a structure. Perhaps, this could be mitigated with validation and/or overriding the default typing in TypeScript.
• May conflict with other libraries that modify global.console. Sequence of configuration may be important if you use an observability solution such as New Relic.

Summary and Room for Improvement

The above implementation could be a solid start for your project, but keep in mind the following points:

1. Inventing a logging library can be a tough, time-consuming job! This article only scratches the surface. As a result, I recommend only inventing the facade (or finding one that works for you!) and using an adapter implementation that wraps a mature logging library, such as winston.js. This will help to address many performance concerns, common features, and issues.
2. Structured logging as JSON is great for observability tools. However, local development DX will suffer when logged detail gets complex enough. DX can be improved by:

   • Using color coding based on log level.

   • Pretty printing vs using compressed JSON syntax (AWS PowerTools logger provides this feature when env var POWERTOOLS_DEV is set to 1 or true). Example pretty printed output could be:

     
        2024-01-08 01:06:28.687Z - ERROR - [scenario] - error-test
        someValue: 1
        someFlag: true
        someString: hello?
        userId: 0e7bc6b9-454b-490a-a506-b20906e0ef3a
        error: Well, that did not work
            at scenario (https://typescript-qmooji.stackblitz.io/~/index.ts:39:16)
            at Object.eval (https://typescript-qmooji.stackblitz.io/~/index.ts:24:1)
            at eval (https://typescript-qmooji.stackblitz.io/~/index.ts:48:4)
            at eval (https://typescript-qmooji.stackblitz.io/~/index.ts:49:3)
            at eval (<anonymous>)
            at Qt (https://c.staticblitz.com/d/webcontainer.a8c70b9797689ab630bc39693935365c46b0aa9d.js:15:30145)
            at https://c.staticblitz.com/d/webcontainer.a8c70b9797689ab630bc39693935365c46b0aa9d.js:15:38799
            at U (https://c.staticblitz.com/d/webcontainer.a8c70b9797689ab630bc39693935365c46b0aa9d.js:15:13565)
            at https://c.staticblitz.com/d/webcontainer.a8c70b9797689ab630bc39693935365c46b0aa9d.js:15:13207
            at boot (https://typescript-qmooji.stackblitz.io/dev/boot:6:3)

   • Filter logging output based on module name. For example, when the env var DEBUG contains module1:*,module2:debug, only these log entries will be output:

     • all log entries for module1
     • debug and higher log entries for module2
3. The need to log expensive operations when in debug mode is common. There are a few strategies to address this:

   1. Use log sampling so that n% of all debug and higher entries are included in output.

   2. Ensure the facade allows for log level detection so that you can do something like:

      if( LoggerFacade.isDebugEnabled() ) {
        const value = await asyncExpensiveCall();
        logger.debug('useful info', { value });
      }

   3. Extend shortcut functions to allow a function to be a factor.

      logger.debug('useful info', {
       // update the contract to allow for () => string | Error | Record<string, object>
       // if a function is included and the current log level matches, evaluate the function
       // get the return value and inject it into logging.
       value: expensiveFn
      });

References

• Logging in .NET Core and ASP.NET Core
• Logging HOWTO (Python)
• Powertools for AWS Lambda (TypeScript)
• You need to sample debug logs in production