Refactor to default to structured logging.

- Added `flattenMessage` and `FlattenedLogMessage` to default to
  structured logging.
- Rework the logic formatting messages for the ConsoleLogger.
- Add a more comprehensive README.

README.md

@@ -0,0 +1,166 @@
+# Overview
+
+`@jdbernard/logging` implements a simple but powerful logging system for
+JavaScript applications based on the idea of heirarchical loggers. It heavily
+inspired by the usage patterns of [log4j][], [logback][], and similar tools in other
+ecosystems.
+
+## Getting Started
+
+Install the package from npm:
+```bash
+npm install @jdbernard/logging
+```
+
+Then, in your application, you can use the logging system like so:
+
+```typescript
+import { logService, ConsoleAppender, LogLevel } from '@jdbernard/logging';
+
+logService.ROOT_LOGGER.appenders.push(new ConsoleAppender(LogLevel.INFO));
+const logger = logService.getLogger('example');
+
+logger.info('Starting application');
+```
+
+## Loggers and Appenders
+
+The logging system is composed of two main components: loggers and appenders.
+Loggers are used to create log events, which are then passed to the appenders
+associated with the logger and it's parent. An appender is a function that
+takes a log event and writes it to some destination, such as the console, a
+file, or a network socket. Appenders also have a logging level threshold, which
+determines which log events are acted upon by the appender.
+
+Loggers are hierarchical, with the hierarchy defined by the logger name. When a
+log message is generated on a *Logger*, it is sent to any appenders associated
+with that logger, and then triggered on the parent logger, being sent to any of
+the parent logger's appenders, and so on up the hierarchy. Similarly, when a
+logging event is generated, it is filtered by the effective logging level of
+the logger. If there is no threshold set on the logger, the effective logging
+level is inherited from the parent logger. This pattern is explained in detail
+in the [logback documentation][effective logging level] and applies in the same
+manner to this library.
+
+Together, the cascading effective logging threshold and the upward propogation
+of log events to parent appenders allows for simple yet fine-grained control
+over the logging output of an application.
+
+## Layouts
+
+One difference from other logging libraries is the absense of layouts. Layouts
+are used in many logging libraries to format the log message before it is
+written to the appender. This requires the assumption of all logs being written
+to a text-based destination, which is not always the case for us.
+
+In this library, all logs are internally stored as structured data, defined by
+the *LogMessage* interface. Notably, the *message* field can be either a string
+or an object, allowing for the addition of arbitrary fields to be added to the
+log event.
+
+The concept of Layouts still has a place, but it has been moved to be an
+implementation detail of the appenders. *ConsoleAppender* accepts a
+*LogMessageFormatter* function allowing for formatting of the resulting
+messages written to the console. the *ApiAppender* would be an example of an
+appender for which layout would be irrelevant.
+
+Finally, notice that all of the appenders provided by this library
+automatically persist log messages as structured data, flattening the `message`
+field if it is an object. *ConsoleAppender* will write the log message as a
+JSON object, promoting fields in the `message` object to top-level fields in
+the output. For example:
+
+```typescript
+import { logService, ConsoleAppender } from '@jdbernard/logging';
+
+logService.ROOT_LOGGER.appenders.push(new ConsoleAppender('TRACE'));
+const logger = logService.getLogger('example');
+
+function someBusinessLogic() {
+  logger.debug({ method: 'someBusinessLogic', msg: 'Doing some business logic', foo: 'bar' });
+}
+
+logger.info('Starting application');
+someBusinessLogic();
+```
+
+results in the following two events logged as output to the console:
+
+```json
+{"timestamp":"2021-09-01T00:00:00.000Z","level":"INFO","scope":"example","message":"Starting application"}
+{"timestamp":"2021-09-01T00:00:00.000Z","level":"DEBUG","scope":"example","msg":"Doing some business logic","method":"someBusinessLogic","foo":"bar"}
+```
+
+Note that the field name in the structured data for string messages is
+"message". In the case of an object message, the fields are used as provided.
+Fields defined on the *LogMessage* interface are reserved and should not be
+used as keys in the message object (and will be ignored if they are). So, for
+example:
+
+```typescript
+logger.debug({ level: 'WARN', message: 'Example of ignored fields', timestamp: 'today' });
+
+results in the following event logged as output to the console (note the
+ignored `level` and `timestamp` fields from the object):
+
+```json
+{"timestamp":"2021-09-01T00:00:00.000Z","level":"DEBUG","scope":"example","message":"Example of ignored fields"}
+```
+
+This flattening behavior is implemented in the `flattenMessage` function
+exported from the `@jdbernard/logging/log-message.ts` module and is available
+for use in custom appender implemetations.
+
+As a final note, the *ConsoleAppender* has some special behavior for the ERROR
+level and *stacktrace* field when running in a web browser to take advantage of
+the console's built-in. See the documentation for the *ConsoleAppender* for
+more information.
+
+## Worked Example
+
+To illustrate the usage of the logging system and the purpose of the
+fine-grained control described above, consider the following TypeScript
+example:
+
+```typescript
+// main.ts -- Entry point of the application
+// A console appender is attached to the root logger to log all events at or
+// above the INFO level.
+logService.ROOT_LOGGER.appenders.push(new ConsoleAppender(LogLevel.INFO));
+
+// An API appender is attached to the root logger to forward all ERROR events
+// to a server-side error log collector.
+logServive.ROOT_LOGGER.appenders.push(new ApiAppender(
+  'https://api.example.com/error-logs',
+  appStore.user.sessionToken,
+  LogLevel.ERROR));
+
+const appLog = logService.getLogger('app');
+appLog.info('Starting application');
+
+// api.ts -- API implementaiton
+const apiLog = logService.getLogger('app/api');
+
+// http-client.ts -- HTTP client implementation
+const httpLog = logService.getLogger('app/api/http-client');
+```
+
+Because different parts of the application use namespaced loggers, we can
+dynamically adjust the logging level of different parts of the application
+without changing the code. For example, to increase the logging level of the
+HTTP client to DEBUG, we can add the following line to the `main.ts` file:
+
+```typescript
+logService.getLogger('app/api/http-client').setLevel(LogLevel.DEBUG);
+```
+
+Additionally, if, for some reason, we only wanted to forward the ERROR events
+from the API namespace to the server-side error log collector, we could attach
+the *ApiAppender* to the `app/api` logger instead of the root logger. This
+would allow us to log all events from both the API and HTTP client loggers to
+the API log collector, but ignore the rest of the application regardless of the
+logging level.
+
+[log4j]: https://logging.apache.org/log4j/2.x/
+[logback]: https://logback.qos.ch/
+[effective logging level]: https://logback.qos.ch/manual/architecture.html#effectiveLevel

package.json

@@ -1,6 +1,6 @@
 {
   "name": "@jdbernard/logging",
-  "version": "1.1.5",
+  "version": "2.0.0",
   "description": "Simple Javascript logging service.",
   "main": "dist/index.js",
   "types": "dist/index.d.ts",

src/api-log-appender.ts

@@ -1,20 +1,13 @@
-import { LogMessage, LogLevel } from './log-message';
+import { LogMessage, LogLevel, flattenMessage, FlattenedLogMessage } from './log-message';
-import LogAppender from './log-appender';
+import { LogAppender } from './log-appender';
 
-interface ApiMessage {
-  level: string;
-  message: string;
-  scope: string;
-  stacktrace: string;
-  timestamp: string;
-}
 export class ApiLogAppender implements LogAppender {
   public batchSize = 10;
   public minimumTimePassedInSec = 60;
   public maximumTimePassedInSec = 120;
   public threshold = LogLevel.ALL;
 
-  private msgBuffer: ApiMessage[] = [];
+  private msgBuffer: FlattenedLogMessage[] = [];
   private lastSent = 0;
 
   constructor(
@@ -33,16 +26,7 @@ export class ApiLogAppender implements LogAppender {
       return;
     }
 
-    this.msgBuffer.push({
+    this.msgBuffer.push(flattenMessage(msg));
-      level: LogLevel[msg.level],
-      message:
-        typeof msg.message === 'string'
-          ? msg.message
-          : JSON.stringify(msg.message),
-      scope: msg.scope,
-      stacktrace: msg.stacktrace,
-      timestamp: msg.timestamp.toISOString()
-    });
   }
 
   private doPost() {

src/console-log-appender.ts

@@ -1,14 +1,22 @@
-/*tslint:disable:no-console*/
+import {
-import { LogMessage, LogLevel } from './log-message';
+  LogLevel,
-import LogAppender from './log-appender';
+  LogMessage,
+  LogMessageFormatter,
+  structuredLogMessageFormatter
+} from './log-message';
+import { LogAppender } from './log-appender';
 
 export class ConsoleLogAppender implements LogAppender {
   public threshold = LogLevel.ALL;
+  public formatter = structuredLogMessageFormatter;
 
-  constructor(threshold?: LogLevel) {
+  constructor(threshold?: LogLevel, formatter?: LogMessageFormatter) {
     if (threshold) {
       this.threshold = threshold;
     }
+    if (formatter) {
+      this.formatter = formatter;
+    }
   }
 
   public appendMessage(msg: LogMessage): void {
@@ -42,12 +50,12 @@ export class ConsoleLogAppender implements LogAppender {
         break;
     }
 
-    if (msg.error) {
+    const strMsg = this.formatter(msg);
-      logMethod(`[${msg.scope}]:`, msg.message, msg.error);
+
-    } else if (msg.stacktrace) {
+    if (msg.error || msg.stacktrace) {
-      logMethod(`[${msg.scope}]:`, msg.message, msg.stacktrace);
+      logMethod(strMsg, msg.error ?? msg.stacktrace);
     } else {
-      logMethod(`[${msg.scope}]:`, msg.message);
+      logMethod(strMsg);
     }
   }
 }

src/log-appender.ts

@@ -1,5 +1,8 @@
 import { LogLevel, LogMessage } from './log-message';
-export default interface LogAppender {
+
+export interface LogAppender {
   threshold: LogLevel;
   appendMessage(message: LogMessage): void;
 }
+
+export default LogAppender;

src/log-message.ts

@@ -1,3 +1,5 @@
+import { omit } from './util'
+
 export enum LogLevel {
   ALL = 0,
   TRACE,
@@ -6,12 +8,15 @@ export enum LogLevel {
   INFO,
   WARN,
   ERROR,
-  FATAL
+  FATAL,
 }
 
-export function parseLogLevel(str: string, defaultLevel = LogLevel.INFO): LogLevel {
+export function parseLogLevel(
-  if (Object.prototype.hasOwnProperty.call(LogLevel, str)) {
+  str: string,
-    return LogLevel[<any>str] as unknown as LogLevel;
+  defaultLevel = LogLevel.INFO,
+): LogLevel {
+  if (str in LogLevel) {
+    return LogLevel[str as keyof typeof LogLevel] as LogLevel;
   } else {
     return defaultLevel;
   }
@@ -20,10 +25,59 @@ export function parseLogLevel(str: string, defaultLevel = LogLevel.INFO): LogLev
 export interface LogMessage {
   scope: string;
   level: LogLevel;
-  message: string | object;
+  message: string | Record<string, unknown>;
-  stacktrace: string;
+  stacktrace?: string;
   error?: Error;
   timestamp: Date;
 }
 
+export type FlattenedLogMessage = Record<string, unknown>;
+
+/**
+ * Flatten a log message to a plain object. The *message* field can be either a
+ * string or an object. In the case of an object message, the LogMessage should
+ * be flattened before being emitted by an appender, promoting the object's
+ * fields to the top level of the message. Fields defined on the *LogMessage*
+ * interface are reserved and should not be used as keys in the message object
+ * (and will be ignored if they are).
+ *
+ * So, for example:
+ *
+ * ```typescript
+ * const logger = logService.getLogger('example');
+ * logger.info({ foo: 'bar', baz: 'qux', timestamp: 'today', level: LogLevel.WARN });
+ * ```
+ *
+ * Should result after flattening in a structured log message like:
+ * ```json
+ * {"scope":"example","level":4,"foo":"bar","baz":"qux","timestamp":"2020-01-01T00:00:00.000Z"}
+ * ```
+ */
+export function flattenMessage(msg: LogMessage): FlattenedLogMessage {
+  if (typeof msg.message === 'string') {
+    return { ...msg };
+  } else {
+    const { message, ...rest } = msg;
+    return {
+      ...omit(message, [
+        'scope',
+        'level',
+        'stacktrace',
+        'error',
+        'timestamp',
+      ]),
+      ...rest,
+    };
+  }
+}
+export type LogMessageFormatter = (msg: LogMessage) => string;
+
+export function structuredLogMessageFormatter(msg: LogMessage): string {
+  return JSON.stringify(flattenMessage(msg));
+}
+
+export function simpleTextLogMessageFormatter(msg: LogMessage): string {
+  return `[${msg.scope}] - ${msg.level}: ${msg.message}`;
+}
+
 export default LogMessage;

src/log-service.ts

@@ -1,10 +1,16 @@
 import { LogLevel } from './log-message';
-import Logger from './logger';
+import { Logger } from './logger';
 
 const ROOT_LOGGER_NAME = 'ROOT';
 
+/**
+ * Service for managing loggers. A LogService instance defines
+ * the service context for a set of loggers. Typically there is only one
+ * LogService instance per application, the one exported as default from this
+ * module.
+ */
 export class LogService {
-  private loggers: { [key: string]: Logger };
+  private loggers: Record<string, Logger>;
 
   public get ROOT_LOGGER() {
     return this.loggers[ROOT_LOGGER_NAME];
@@ -15,10 +21,38 @@ export class LogService {
     this.loggers[ROOT_LOGGER_NAME] = new Logger(
       ROOT_LOGGER_NAME,
       undefined,
-      LogLevel.ALL
+      LogLevel.ALL,
     );
   }
 
+  /**
+   * Get a logger by name. If the logger does not exist, it will be created.
+   * Loggers are hierarchical, with the heirarchy defined by the logger name.
+   * When creating a new logger, the parent logger is determined by the longest
+   * existing logger name that is a prefix of the new logger name. For example,
+   * if a logger with the name "foo" already exists, any subsequent loggers
+   * with the names "foo.bar", "foo/bar", "foolish.choice", etc. will be
+   * created as children of the "foo" logger.
+   *
+   * As another example, given the following invocations:
+   *
+   * ```typescript
+   * logService.getLogger('foo');
+   * logService.getLogger('foo.bar');
+   * logService.getLogger('foo.bar.baz');
+   * logService.getLogger('foo.qux');
+   * ```
+   *
+   * will result in the following logging hierarchy:
+   *
+   *     foo
+   *     ├─foo.bar
+   *     │ └─foo.bar.baz
+   *     └─foo.qux
+   *
+   * See the Logger class for details on how loggers are used and the
+   * implications of the logger hierarchy.
+   */
   public getLogger(name: string, threshold?: LogLevel): Logger {
     if (this.loggers[name]) {
       return this.loggers[name];
@@ -30,7 +64,7 @@ export class LogService {
       .filter((n: string) => name.startsWith(n))
       .reduce(
         (acc: string, cur: string) => (acc.length > cur.length ? acc : cur),
-        ''
+        '',
       );
 
     if (parentLoggerName) {

src/logger.ts

@@ -1,16 +1,52 @@
-import { LogMessage, LogLevel } from './log-message';
+import { LogLevel, LogMessage } from './log-message';
-import LogAppender from './log-appender';
+import { LogAppender } from './log-appender';
 
-export type DeferredMsg = () => string | object;
+export type DeferredMsg = () => string | Record<string, unknown>;
-export type MessageType = string | DeferredMsg | object;
+export type MessageType = string | DeferredMsg | Record<string, unknown>;
 
+export function isDeferredMsg(msg: MessageType): msg is DeferredMsg {
+  return typeof msg === 'function';
+}
+
+/**
+ * Logger class for logging messages.
+ *
+ * Loggers are used to log messages at different levels. The levels are, in
+ * order of increasing severity: TRACE, DEBUG, LOG, INFO, WARN, ERROR, FATAL.
+ * Log messages can be logged at a specific level by calling the corresponding
+ * method on the logger instance. For example, to log a message at the INFO
+ * level, call the *info* method on the logger.
+ *
+ * Loggers have a threshold level, which is the minimum level of log message
+ * that will be logged by the logger. Log messages with a level below the
+ * threshold will be ignored. The threshold level can be set when creating a
+ * logger, or by calling the *setThreshold* method on an existing logger. If a
+ * threshold is not set, the logger will use the threshold of its parent
+ * logger.
+ *
+ * Loggers are hierarchical, with the hierarchy defined by the logger name.
+ * The heirarchy is tracked by the children: child loggers have a link to their
+ * parents, while parent loggers do not have a list of their children.
+ *
+ * When a log message is logged by a logger, it is sent to all of the appenders
+ * attached to the logger and to the parent logger. Appenders can be attached
+ * to any Logger instance, but, because of this upwards propogation, appenders
+ * are usually attached to the root logger, which is an ancestor of all loggers
+ * created by the same LogService instance.
+ *
+ * Loggers are typically created and managed by a LogService instance.  The
+ * *LogService#getLogger* method is used to get a logger by name, creating it
+ * if necessary. When creating a new logger, the parent logger is determined by
+ * the longest existing logger name that is a prefix of the new logger name.
+ * For more details, see *LogService#getLogger*.
+ */
 export class Logger {
   public appenders: LogAppender[] = [];
 
   public constructor(
     public readonly name: string,
     private parentLogger?: Logger,
-    public threshold?: LogLevel
+    public threshold?: LogLevel,
   ) {}
 
   public createChildLogger(name: string, threshold?: LogLevel): Logger {
@@ -20,7 +56,7 @@ export class Logger {
   public doLog(
     level: LogLevel,
     message: Error | MessageType,
-    stacktrace?: string
+    stacktrace?: string,
   ): void {
     if (level < this.getEffectiveThreshold()) {
       return;
@@ -31,20 +67,20 @@ export class Logger {
       level,
       message: '',
       stacktrace: '',
-      timestamp: new Date()
+      timestamp: new Date(),
     };
 
     if (message === undefined || message === null) {
       logMsg.message = message;
-      logMsg.stacktrace = stacktrace == null ? '' : stacktrace;
+      logMsg.stacktrace = stacktrace ?? '';
-    } else if ((message as DeferredMsg).call !== undefined) {
-      logMsg.message = (message as DeferredMsg)();
-      logMsg.stacktrace = stacktrace == null ? '' : stacktrace;
     } else if (message instanceof Error) {
       const error = message as Error;
       logMsg.error = error;
       logMsg.message = `${error.name}: ${error.message}`;
-      logMsg.stacktrace = error.stack == null ? '' : error.stack;
+      logMsg.stacktrace = stacktrace ?? error.stack ?? '';
+    } else if (isDeferredMsg(message)) {
+      logMsg.message = message();
+      logMsg.stacktrace = stacktrace == null ? '' : stacktrace;
     } else {
       // string | object
       logMsg.message = message;
@@ -83,7 +119,7 @@ export class Logger {
   }
 
   protected sendToAppenders(logMsg: LogMessage) {
-    this.appenders.forEach(app => {
+    this.appenders.forEach((app) => {
       app.appendMessage(logMsg);
     });
 

src/util.ts

@@ -0,0 +1,12 @@
+export function omit(
+  obj: Record<string, unknown>,
+  keys: string[],
+): Record<string, unknown> {
+  const result: Record<string, unknown> = {};
+  for (const key in obj) {
+    if (!keys.includes(key)) {
+      result[key] = obj[key];
+    }
+  }
+  return result;
+}