From f915a35fb4ba00a8adb189b728842d6e2f966ed0 Mon Sep 17 00:00:00 2001 From: Matt Luedke Date: Tue, 5 Mar 2019 13:55:12 -0500 Subject: [PATCH] feat: Add basic logger (#20) --- src/Request.ts | 23 +- src/Router.ts | 4 +- src/interfaces.ts | 7 + src/logging/ConsoleLogger.ts | 108 ++++++++++ src/logging/is-debug-level-or-more-verbose.ts | 11 + src/logging/levels.ts | 36 ++++ src/logging/logging-types.ts | 200 ++++++++++++++++++ src/request-response-types.ts | 5 + src/utils/common-types.ts | 2 + tests/Request.test.ts | 42 ++++ tests/logging/ConsoleLogger.test.ts | 187 ++++++++++++++++ 11 files changed, 620 insertions(+), 5 deletions(-) create mode 100644 src/logging/ConsoleLogger.ts create mode 100644 src/logging/is-debug-level-or-more-verbose.ts create mode 100644 src/logging/levels.ts create mode 100644 src/logging/logging-types.ts create mode 100644 tests/logging/ConsoleLogger.test.ts diff --git a/src/Request.ts b/src/Request.ts index a8b2a20..2fbaa00 100644 --- a/src/Request.ts +++ b/src/Request.ts @@ -1,14 +1,16 @@ +import { ILogger } from './logging/logging-types'; import _ from 'underscore'; import qs from 'qs'; import cookie from 'cookie'; import Application from './Application'; -import { RequestEvent, HandlerContext, RequestEventRequestContext } from './request-response-types'; +import { RequestEvent, HandlerContext, RequestEventRequestContext, LambdaEventSourceType } from './request-response-types'; import { StringMap, KeyValueStringObject, StringArrayOfStringsMap, StringUnknownMap } from './utils/common-types'; +import ConsoleLogger from './logging/ConsoleLogger'; export default class Request { - public static readonly SOURCE_ALB = 'ALB'; - public static readonly SOURCE_APIGW = 'APIGW'; + public static readonly SOURCE_ALB: LambdaEventSourceType = 'ALB'; + public static readonly SOURCE_APIGW: LambdaEventSourceType = 'APIGW'; /** * The application that is running this request. @@ -204,7 +206,7 @@ export default class Request { * Load Balancer, `ALB`, or API Gateway, `APIGW`). See `Request.SOURCE_ALB` and * `Request.SOURCE_APIGW`. */ - public readonly eventSourceType: ('ALB' | 'APIGW'); + public readonly eventSourceType: LambdaEventSourceType; /** * The body of the request. If the body is an empty value (e.g. `''`), `req.body` will @@ -215,6 +217,8 @@ export default class Request { */ public body?: unknown; + public readonly log: ILogger; + protected _parentRequest?: Request; protected _url: string; protected _path: string; @@ -269,6 +273,17 @@ export default class Request { // more details. this.originalUrl = event.path; this.params = Object.freeze(params); + + if (this._parentRequest) { + this.log = this._parentRequest.log; + } else { + this.log = new ConsoleLogger({ + level: app.routerOptions.logging.level, + interface: this.eventSourceType, + fnStartTime: Date.now(), + getTimeUntilFnTimeout: () => { return context.getRemainingTimeInMillis(); }, + }); + } } /** PUBLIC PROPERTIES: GETTERS AND SETTERS */ diff --git a/src/Router.ts b/src/Router.ts index 32b5b7a..bd32fc8 100644 --- a/src/Router.ts +++ b/src/Router.ts @@ -16,9 +16,11 @@ import { RouteMatchingProcessorChain } from './chains/RouteMatchingProcessorChai import { MatchAllRequestsProcessorChain } from './chains/MatchAllRequestsProcessorChain'; import { SubRouterProcessorChain } from './chains/SubRouterProcessorChain'; import Route from './Route'; +import { Optional } from './utils/common-types'; const DEFAULT_OPTS: RouterOptions = { caseSensitive: false, + logging: { level: 'info' }, }; export default class Router implements IRouter { @@ -26,7 +28,7 @@ export default class Router implements IRouter { public readonly routerOptions: RouterOptions; private readonly _processors: IRequestMatchingProcessorChain[] = []; - public constructor(options?: RouterOptions) { + public constructor(options?: Optional) { this.routerOptions = _.defaults(options, DEFAULT_OPTS); } diff --git a/src/interfaces.ts b/src/interfaces.ts index 50da097..03b24a7 100644 --- a/src/interfaces.ts +++ b/src/interfaces.ts @@ -2,6 +2,7 @@ import Request from './Request'; import Response from './Response'; +import { LogLevel } from './logging/logging-types'; /** * The function that is passed to request processors for them to signal that they are done @@ -91,6 +92,10 @@ export interface RouteMatchingProcessorAppender { (path: PathParams, ...handlers: ProcessorOrProcessors[]): T; } +export interface ApplicationLoggingOptions { + level: LogLevel; +} + export interface RouterOptions { /** @@ -100,6 +105,8 @@ export interface RouterOptions { * case-sensitivity enabled, only the second request would match that route. */ caseSensitive: boolean; + + logging: ApplicationLoggingOptions; } export interface IRouter { diff --git a/src/logging/ConsoleLogger.ts b/src/logging/ConsoleLogger.ts new file mode 100644 index 0000000..c024c14 --- /dev/null +++ b/src/logging/ConsoleLogger.ts @@ -0,0 +1,108 @@ +import _ from 'underscore'; +import { + ILogger, + LogObject, + LoggerConfig, + LogLevel, + DebugLogObject, +} from './logging-types'; +import levels from './levels'; +import isDebugLevelOrMoreVerbose from './is-debug-level-or-more-verbose'; +import { LambdaEventSourceType } from '../request-response-types'; + +export default class ConsoleLogger implements ILogger { + + protected _level: LogLevel; + protected _interface: LambdaEventSourceType; + protected _getTimeUntilFnTimeout: () => number; + protected _fnStartTime: number; + + public constructor(config: LoggerConfig) { + this._level = config.level || 'info'; + this._interface = config.interface; + this._fnStartTime = typeof config.fnStartTime === 'undefined' ? Date.now() : config.fnStartTime; + this._getTimeUntilFnTimeout = config.getTimeUntilFnTimeout; + } + + public trace(msg: string, data?: unknown): void { + this._log('trace', msg, data); + } + + public debug(msg: string, data?: unknown): void { + this._log('debug', msg, data); + } + + public info(msg: string, data?: unknown): void { + this._log('info', msg, data); + } + + public warn(msg: string, data?: unknown): void { + this._log('warn', msg, data); + } + + public error(msg: string, data?: unknown): void { + this._log('error', msg, data); + } + + public fatal(msg: string, data?: unknown): void { + this._log('fatal', msg, data); + } + + public getLevel(): LogLevel { + return this._level; + } + + public setLevel(level: LogLevel): void { + this._level = level; + } + + /** + * Perform the actual message logging + */ + protected _log(level: LogLevel, msg: string, data?: unknown): void { + if (this._shouldLog(level)) { + // eslint-disable-next-line no-console + console.log(JSON.stringify(this._makeLogObject(level, msg, data))); + } + } + + /** + * @returns `true` if the given level should be logged at this logger's current log + * level setting. + */ + protected _shouldLog(level: LogLevel): boolean { + // Log if the level is higher priority than the current log level setting. + // e.g. error (50) >= info (30) + return levels[level] >= levels[this._level]; + } + + /** + * Creates an object to be logged + */ + protected _makeLogObject(level: LogLevel, msg: string, data?: unknown): LogObject | DebugLogObject { + let logLine: LogObject = { level, msg }; + + if (!_.isUndefined(data)) { + logLine.data = data; + } + + if (isDebugLevelOrMoreVerbose(level)) { + let debugLogLine = logLine as DebugLogObject; + + debugLogLine.int = this._interface; + debugLogLine.remaining = this._getTimeUntilFnTimeout(); + debugLogLine.timer = this._getTimeSinceFnStart(); + + return debugLogLine; + } + + return logLine; + } + + /** + * The approximate time, in milliseconds, since the Lambda function started executing. + */ + protected _getTimeSinceFnStart(): number { + return Date.now() - this._fnStartTime; + } +} diff --git a/src/logging/is-debug-level-or-more-verbose.ts b/src/logging/is-debug-level-or-more-verbose.ts new file mode 100644 index 0000000..9c0c20e --- /dev/null +++ b/src/logging/is-debug-level-or-more-verbose.ts @@ -0,0 +1,11 @@ +import { LogLevel } from './logging-types'; +import levels from './levels'; + +/** + * @returns `true` if the given log level is `'debug'` or a more verbose level (e.g. + * `'trace'`). + */ +export default function isDebugLevelOrMoreVerbose(level: LogLevel): boolean { + // More verbose levels have lower priority numbers + return levels[level] <= levels.debug; +} diff --git a/src/logging/levels.ts b/src/logging/levels.ts new file mode 100644 index 0000000..3b33929 --- /dev/null +++ b/src/logging/levels.ts @@ -0,0 +1,36 @@ +import { LogLevels } from './logging-types'; + +/** + * A map of all available log levels. The key is the `LogLevelLabel` and the value is the + * "priority". The logger's log level is set to one of these keys. When a message logging + * function such as `debug` is called, it is only logged if the message's "priority" is + * greater than or equal to the priority of the current log level. For example: + * + * ``` + * const logger = new ConsoleLogger({ + * level: 'info', + * interface: 'ALB', + * getTimeUntilFnTimeout: () => { return 0; } + * }); + * + * // error (priority: 50) is >= info (priority: 30), so this message is logged + * logger.error('error'); + * + * // debug (priority: 20) is NOT >= info (priority 30), so this message is NOT logged + * logger.debug('debug'); + * ``` + * + * Logging level priorities are for internal use and are not exposed on the public API. + * Users of the public API adjust the logging level using the `LogLevel` strings. + */ +const levels: LogLevels = { + trace: 10, + debug: 20, + info: 30, + warn: 40, + error: 50, + fatal: 60, + silent: Number.MAX_SAFE_INTEGER, +}; + +export default levels; diff --git a/src/logging/logging-types.ts b/src/logging/logging-types.ts new file mode 100644 index 0000000..e094b67 --- /dev/null +++ b/src/logging/logging-types.ts @@ -0,0 +1,200 @@ +/* istanbul ignore next */ + +import { LambdaEventSourceType } from '../request-response-types'; + +/** + * A union of all available logging levels. + * + * @see ILogger#setLevel + */ +export type LogLevel = 'trace' | 'debug' | 'info' | 'warn' | 'error' | 'fatal' | 'silent'; + +export interface ILogger { + + /** + * Log a message at the `trace` log level. The logger will only log a message for this + * method if the log level is set to `trace`. + * + * @param msg The message to log + * @param data Custom data to add to the log message. Added to the log object under the + * `data` key. + */ + trace(msg: string, data: unknown): void; + + /** + * Log a message at the `debug` log level. The logger will only log a message for this + * method if the log level is set to `'debug'`, or a more verbose level. + * + * @param msg The message to log + * @param data Custom data to add to the log message. Added to the log object under the + * `data` key. + */ + debug(msg: string, data: unknown): void; + + /** + * Log a message at the `info` log level. The logger will only log a message for this + * method if the log level is set to `'info'`, or a more verbose level. + * + * @param msg The message to log + * @param data Custom data to add to the log message. Added to the log object under the + * `data` key. + */ + info(msg: string, data: unknown): void; + + /** + * Log a message at the `warn` log level. The logger will only log a message for this + * method if the log level is set to `'warn'`, or a more verbose level. + * + * @param msg The message to log + * @param data Custom data to add to the log message. Added to the log object under the + * `data` key. + */ + warn(msg: string, data: unknown): void; + + /** + * Log a message at the `error` log level. The logger will only log a message for this + * method if the log level is set to `'error'`, or a more verbose level. + * + * @param msg The message to log + * @param data Custom data to add to the log message. Added to the log object under the + * `data` key. + */ + error(msg: string, data: unknown): void; + + /** + * Log a message at the `fatal` log level. The logger will always log a message unless + * the log level is set to `'silent'`. + * + * @param msg The message to log + * @param data Custom data to add to the log message. Added to the log object under the + * `data` key. + */ + fatal(msg: string, data: unknown): void; + + /** + * Gets the current logging level. + * + * @see `setLogLevel` + */ + getLevel(): LogLevel; + + /** + * Sets the log level. This is a list of all available log levels, ordered from most + * verbose to least verbose: + * + * * `trace` + * * `debug` + * * `info` + * * `warn` + * * `error` + * * `fatal` + * * `silent` + * + * The logger's level determines which messages are logged and which ones are ignored. + * When the logger's level is set to one of these values, any message that is given to + * the logger to be logged with a level that is *more verbose* than the logger's + * current log level will *not* be logged. For example: + * + * ``` + * // Note that this logger's level is set to `info` + * const logger = new ConsoleLogger({ + * level: 'info', + * interface: 'ALB', + * getTimeUntilFnTimeout: () => { return 0; } + * }); + * + * // `error` is *less* verbose than `info` so this message is logged + * logger.error('error'); + * + * // `debug` is *more* verbose than `info`, so this message is NOT logged + * logger.debug('debug'); + * + * logger.setLevel('trace'); + * // `debug` is *less* verbose than `trace`, so this message is logged + * logger.debug('debug'); + * ``` + * + * Setting the log level to `'silent'` disables all logging. + */ + setLevel(level: LogLevel): void; + +} + +// We have to use a `type` instead of an `interface` here because interfaces do not +// support indexes using `key in`. +export type LogLevels = { + readonly [key in LogLevel]: number; +}; + +/** + * Configuration to initialize a `Logger` with. + */ +export interface LoggerConfig { + + /** + * The type of event interface that triggered the current `Request`. + */ + interface: LambdaEventSourceType; + + /** + * The current Lambda function's timeout threshold, in milliseconds. + */ + getTimeUntilFnTimeout: () => number; + + /** + * The current log level. See description on `ILogger#setLevel`. + * + * @default 'info' + */ + level?: LogLevel; + + /** + * The epoch time (in milliseconds) at which the current Lambda function was triggered. + */ + fnStartTime?: number; + +} + +/** + * The format of a standard log line. + */ +export interface LogObject { + + /** + * @see LogLevel + */ + level: LogLevel; + + /** + * The message to log. + */ + msg: string; + + /** + * Any kind of data to add to the logged JSON object. + */ + data?: unknown; + +} + +/** + * The format of a log line with extra debugging info added. + */ +export interface DebugLogObject extends LogObject { + + /** + * Execution time, in milliseconds, up until log was generated. + */ + timer: number; + + /** + * The remaining milliseconds until the Lambda function times out. + */ + remaining: number; + + /** + * The Lambda event source type that triggered the current `Request`. + */ + int: LambdaEventSourceType; + +} diff --git a/src/request-response-types.ts b/src/request-response-types.ts index 2259c59..5652ec3 100644 --- a/src/request-response-types.ts +++ b/src/request-response-types.ts @@ -138,3 +138,8 @@ export interface CookieOpts { // https://expressjs.com/en/api.html#res.cookie // https://expressjs.com/en/api.html#req.signedCookies } + +/** + * The types of Lambda event sources that can trigger a Request. + */ +export type LambdaEventSourceType = 'APIGW' | 'ALB'; diff --git a/src/utils/common-types.ts b/src/utils/common-types.ts index 4f9c984..ed95855 100644 --- a/src/utils/common-types.ts +++ b/src/utils/common-types.ts @@ -6,6 +6,8 @@ export interface StringArrayOfStringsMap { [s: string]: string[] } export interface KeyValueStringObject { [k: string]: (string | string[] | KeyValueStringObject) } // Removes `readonly` modifier and make all keys writable again export type Writable = { -readonly [P in keyof T]-?: T[P] }; +// Makes all keys on an object optional +export type Optional = { [P in keyof T]? : T[P] }; export function isStringMap(o: any): o is StringMap { if (!_.isObject(o) || _.isArray(o)) { // because arrays are objects diff --git a/tests/Request.test.ts b/tests/Request.test.ts index 7cd4d44..9828216 100644 --- a/tests/Request.test.ts +++ b/tests/Request.test.ts @@ -4,6 +4,9 @@ import { Request, Application } from '../src'; import { RequestEvent } from '../src/request-response-types'; import { apiGatewayRequest, handlerContext, albRequest, albMultiValHeadersRequest } from './samples'; import { isKeyValueStringObject } from '../src/utils/common-types'; +import ConsoleLogger from '../src/logging/ConsoleLogger'; +import sinon from 'sinon'; +import { DebugLogObject } from '../src/logging/logging-types'; describe('Request', () => { let app: Application, allRequestTypes: Request[], allEventTypes: RequestEvent[]; @@ -561,4 +564,43 @@ describe('Request', () => { }); + describe('`log` property', () => { + + function testLog(req: Request): void { + let consoleSpy = sinon.spy(console, 'log'), + logLine: DebugLogObject; + + expect(req.log).to.be.an.instanceOf(ConsoleLogger); + + // Set level to `debug` to test full debug log line + req.log.setLevel('debug'); + req.log.debug('test', { test: true }); + + sinon.assert.calledOnce(consoleSpy); + + logLine = JSON.parse(consoleSpy.firstCall.args[0]); + expect(logLine.msg).to.strictlyEqual('test'); + expect(logLine.data).to.eql({ test: true }); + expect(logLine.remaining).to.be.a('number'); + expect(logLine.timer).to.be.a('number'); + + consoleSpy.restore(); + } + + it('exists and logs messages', () => { + let req = new Request(app, apiGatewayRequest(), handlerContext()); + + testLog(req); + }); + + it('is inherited from parent requests to sub-requests', () => { + let req = new Request(app, apiGatewayRequest(), handlerContext()), + subReq = req.makeSubRequest(''); + + testLog(subReq); + expect(subReq.log).to.strictlyEqual(req.log); + }); + + }); + }); diff --git a/tests/logging/ConsoleLogger.test.ts b/tests/logging/ConsoleLogger.test.ts new file mode 100644 index 0000000..5c578cb --- /dev/null +++ b/tests/logging/ConsoleLogger.test.ts @@ -0,0 +1,187 @@ +import { + LogObject, + LogLevel, + DebugLogObject, + LoggerConfig, +} from './../../src/logging/logging-types'; +import levels from '../../src/logging/levels'; +import isDebugLevelOrMoreVerbose from '../../src/logging/is-debug-level-or-more-verbose'; +import { expect } from 'chai'; +import ConsoleLogger from '../../src/logging/ConsoleLogger'; +import _ from 'underscore'; +import sinon, { SinonSpy } from 'sinon'; + +describe('ConsoleLogger', () => { + + const DEFAULT_LOGGER_CONFIG: LoggerConfig = { + interface: 'ALB', + getTimeUntilFnTimeout: () => { return 0; }, + }; + + let logSpy: SinonSpy; + + beforeEach(function() { + logSpy = sinon.spy(console, 'log'); + }); + + afterEach(function() { + logSpy.restore(); + }); + + describe('constructor', () => { + + it('defaults log level to "info"', () => { + let logger = new ConsoleLogger({ interface: 'ALB', getTimeUntilFnTimeout: _.constant(0), fnStartTime: 0 }); + + expect(logger.getLevel()).to.strictlyEqual('info'); + }); + + }); + + function findLessVerboseLogLevel(level: LogLevel): LogLevel | undefined { + if (_.isUndefined(levels[level])) { + return undefined; + } + return _.find(_.keys(levels) as LogLevel[], (potentiallyLessVerboseLevel) => { + return levels[potentiallyLessVerboseLevel] > levels[level]; + }); + } + + function setupTestLogger(level: LogLevel): ConsoleLogger { + return new ConsoleLogger(_.extend({}, DEFAULT_LOGGER_CONFIG, { level })); + } + + function getLogLineAsString(index: number = 0): string { + return logSpy.firstCall.args[index]; + } + + function getLogLineAsJSON(index: number = 0): LogObject | DebugLogObject { + return JSON.parse(getLogLineAsString(index)); + } + + function createLoggerAndTest(level: Exclude): ConsoleLogger { + let logger = setupTestLogger(level), + data = { customData: true, otherOption: { nested: 'yes' } }, + msg = 'My log message', + logLine: LogObject | DebugLogObject; + + logger[level](msg, data); + + // Expect that we've only logged one message to the console + sinon.assert.calledOnce(logSpy); + + logLine = getLogLineAsJSON(0); + + expect(getLogLineAsString(0)).to.be.a('string'); + expect(logLine).to.be.an('object'); + expect(logLine.level).to.strictlyEqual(level); + expect(logLine.msg).to.strictlyEqual(msg); + expect(logLine.data).to.eql(data); + + if (isDebugLevelOrMoreVerbose(level)) { + let debugLogLine = logLine as DebugLogObject; + + expect(debugLogLine.int).to.strictlyEqual(DEFAULT_LOGGER_CONFIG.interface); + expect(debugLogLine.timer).to.be.a('number'); + expect(debugLogLine.remaining).to.be.a('number'); + expect(debugLogLine.remaining).to.be.strictlyEqual(DEFAULT_LOGGER_CONFIG.getTimeUntilFnTimeout()); + } + + return logger; + } + + function createLogFunctionTest(level: Exclude): void { + describe(level, () => { + + it('logs a message in the correct format', () => { + createLoggerAndTest(level); + }); + + const lessVerboseLevel = findLessVerboseLogLevel(level); + + // Only perform the following test if there is a less verbose logging level + // available. If a less verbose level does not exist, then there is no way to + // filter the log message. + if (lessVerboseLevel) { + it('does not log a message when log level is less verbose', () => { + let logger = setupTestLogger(lessVerboseLevel); + + logger[level]('test'); + + sinon.assert.notCalled(logSpy); + }); + } + }); + } + + // Set up tests for each available log level + _.forEach(_.keys(levels) as LogLevel[], (level: LogLevel) => { + if (level !== 'silent') { + createLogFunctionTest(level); + } + }); + + describe('log level "silent"', () => { + + it('does not log any messages', () => { + let logger = setupTestLogger('silent'); + + _.forEach(_.keys(levels) as LogLevel[], (level: LogLevel) => { + if (level !== 'silent') { + logger[level]('test'); + } + }); + + sinon.assert.notCalled(logSpy); + }); + + }); + + describe('getLevel', () => { + + it('gets the log level', () => { + let logger = new ConsoleLogger({ level: 'warn', interface: 'APIGW', getTimeUntilFnTimeout: _.constant(2000) }); + + expect(logger.getLevel()).to.strictlyEqual('warn'); + }); + + }); + + describe('setLevel', () => { + + it('allows updating the log level', () => { + let logger = createLoggerAndTest('info'); + + // Reset logSpy's history after createLoggerAndTest's tests + logSpy.resetHistory(); + + expect(logger.getLevel()).to.strictlyEqual('info'); + + logger.setLevel('fatal'); + + expect(logger.getLevel()).to.strictlyEqual('fatal'); + + logger.trace('trace message'); + sinon.assert.notCalled(logSpy); + logSpy.resetHistory(); + + logger.debug('debug message'); + sinon.assert.notCalled(logSpy); + logSpy.resetHistory(); + + logger.warn('warn message'); + sinon.assert.notCalled(logSpy); + logSpy.resetHistory(); + + logger.error('error message'); + sinon.assert.notCalled(logSpy); + logSpy.resetHistory(); + + logger.fatal('fatal message'); + sinon.assert.calledOnce(logSpy); + expect(logSpy.firstCall.args[0]).to.be.a('string'); + }); + + }); + +});