From c3e2152afbb2a9af8fee3848f851a2611be08cbb Mon Sep 17 00:00:00 2001 From: Jonathan Bernard Date: Thu, 2 Jan 2025 17:03:52 -0600 Subject: [PATCH] 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 | 166 ++++++++++++++++++++++++++++++++++++ package.json | 2 +- src/api-log-appender.ts | 24 +----- src/console-log-appender.ts | 26 ++++-- src/log-appender.ts | 5 +- src/log-message.ts | 66 ++++++++++++-- src/log-service.ts | 42 ++++++++- src/logger.ts | 62 +++++++++++--- src/util.ts | 12 +++ 9 files changed, 351 insertions(+), 54 deletions(-) create mode 100644 README.md create mode 100644 src/util.ts diff --git a/README.md b/README.md new file mode 100644 index 0000000..daf24c3 --- /dev/null +++ b/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 diff --git a/package.json b/package.json index a9d9f19..346f4b6 100644 --- a/package.json +++ b/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", diff --git a/src/api-log-appender.ts b/src/api-log-appender.ts index 6ec0b46..cfd98a0 100644 --- a/src/api-log-appender.ts +++ b/src/api-log-appender.ts @@ -1,20 +1,13 @@ -import { LogMessage, LogLevel } from './log-message'; -import LogAppender from './log-appender'; +import { LogMessage, LogLevel, flattenMessage, FlattenedLogMessage } from './log-message'; +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({ - 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() - }); + this.msgBuffer.push(flattenMessage(msg)); } private doPost() { diff --git a/src/console-log-appender.ts b/src/console-log-appender.ts index 6e08717..4e43c7f 100644 --- a/src/console-log-appender.ts +++ b/src/console-log-appender.ts @@ -1,14 +1,22 @@ -/*tslint:disable:no-console*/ -import { LogMessage, LogLevel } from './log-message'; -import LogAppender from './log-appender'; +import { + LogLevel, + 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) { - logMethod(`[${msg.scope}]:`, msg.message, msg.error); - } else if (msg.stacktrace) { - logMethod(`[${msg.scope}]:`, msg.message, msg.stacktrace); + const strMsg = this.formatter(msg); + + if (msg.error || msg.stacktrace) { + logMethod(strMsg, msg.error ?? msg.stacktrace); } else { - logMethod(`[${msg.scope}]:`, msg.message); + logMethod(strMsg); } } } diff --git a/src/log-appender.ts b/src/log-appender.ts index 99a675c..853af41 100644 --- a/src/log-appender.ts +++ b/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; diff --git a/src/log-message.ts b/src/log-message.ts index 266b1dc..81956b6 100644 --- a/src/log-message.ts +++ b/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 { - if (Object.prototype.hasOwnProperty.call(LogLevel, str)) { - return LogLevel[str] as unknown as LogLevel; +export function parseLogLevel( + str: string, + 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; - stacktrace: string; + message: string | Record; + stacktrace?: string; error?: Error; timestamp: Date; } +export type FlattenedLogMessage = Record; + +/** + * 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; diff --git a/src/log-service.ts b/src/log-service.ts index b338c4a..5e3cd55 100644 --- a/src/log-service.ts +++ b/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; 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) { diff --git a/src/logger.ts b/src/logger.ts index b5aab6f..48b6333 100644 --- a/src/logger.ts +++ b/src/logger.ts @@ -1,16 +1,52 @@ -import { LogMessage, LogLevel } from './log-message'; -import LogAppender from './log-appender'; +import { LogLevel, LogMessage } from './log-message'; +import { LogAppender } from './log-appender'; -export type DeferredMsg = () => string | object; -export type MessageType = string | DeferredMsg | object; +export type DeferredMsg = () => string | Record; +export type MessageType = string | DeferredMsg | Record; +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; - } else if ((message as DeferredMsg).call !== undefined) { - logMsg.message = (message as DeferredMsg)(); - logMsg.stacktrace = stacktrace == null ? '' : stacktrace; + logMsg.stacktrace = 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); }); diff --git a/src/util.ts b/src/util.ts new file mode 100644 index 0000000..0da6605 --- /dev/null +++ b/src/util.ts @@ -0,0 +1,12 @@ +export function omit( + obj: Record, + keys: string[], +): Record { + const result: Record = {}; + for (const key in obj) { + if (!keys.includes(key)) { + result[key] = obj[key]; + } + } + return result; +}