From 82abf480d9b4c7d87f9df6d3862adb7e9851dd71 Mon Sep 17 00:00:00 2001 From: Taranveer Virk Date: Tue, 21 Nov 2017 10:45:39 -0500 Subject: [PATCH] Impl (#3) * Implement log extension * update exports + tweaks * acceptance test and readme * Feedback applied * add minimum engines field * feedback applied * feedback * refactor to be more debuggable * apply feedback * apply feedback. updated readme to use cli * quick update --- README.md | 366 +++++++++++++++++- index.ts | 2 +- package.json | 20 +- src/component.ts | 16 + src/decorators/log.decorator.ts | 44 +++ src/index.ts | 13 + src/keys.ts | 25 ++ src/mixins/log-level.mixin.ts | 45 +++ src/providers/log-action.provider.ts | 92 +++++ src/providers/log-level.provider.ts | 15 + src/providers/timer.provider.ts | 18 + src/types.ts | 26 ++ test/acceptance/log.extension.acceptance.ts | 327 ++++++++++++++++ test/mocha.opts | 2 + test/unit/decorators/log.decorator.unit.ts | 29 ++ test/unit/mixins/log-level.mixin.unit.ts | 36 ++ .../providers/log-action.provider.unit.ts | 83 ++++ .../unit/providers/log-level.provider.unit.ts | 14 + test/unit/providers/timer.provider.unit.ts | 26 ++ 19 files changed, 1188 insertions(+), 11 deletions(-) create mode 100644 src/component.ts create mode 100644 src/decorators/log.decorator.ts create mode 100644 src/index.ts create mode 100644 src/keys.ts create mode 100644 src/mixins/log-level.mixin.ts create mode 100644 src/providers/log-action.provider.ts create mode 100644 src/providers/log-level.provider.ts create mode 100644 src/providers/timer.provider.ts create mode 100644 src/types.ts create mode 100644 test/acceptance/log.extension.acceptance.ts create mode 100644 test/mocha.opts create mode 100644 test/unit/decorators/log.decorator.unit.ts create mode 100644 test/unit/mixins/log-level.mixin.unit.ts create mode 100644 test/unit/providers/log-action.provider.unit.ts create mode 100644 test/unit/providers/log-level.provider.unit.ts create mode 100644 test/unit/providers/timer.provider.unit.ts diff --git a/README.md b/README.md index bbbb811..55b8d49 100644 --- a/README.md +++ b/README.md @@ -1,2 +1,364 @@ -# lb4-log-extension-example -An example repo showing how to write a complex log extension +# loopback4-example-log-extension +An example repo showing how to write a complex log extension for LoopBack 4 + +## Overview + +This repository shows you how to use [@loopback/cli](https://github.com/strongloop/loopback-next/tree/master/packages/cli) +to write a complex logging extension that requires a [Component](http://loopback.io/doc/en/lb4/Using-components.html), +[Decorator](http://loopback.io/doc/en/lb4/Decorators.html), and a [Mixin](http://loopback.io/doc/en/lb4/Mixin.html). + +To use the extension, load the component to get access to a `LogFn` that can be +used in a sequence to log information. A Mixin allows you to set the +application wide logLevel. Only Controller methods configured at or above the +logLevel will be logged. + +Possible levels are: DEBUG < INFO < WARN < ERROR < OFF + +*Possible levels are represented as numbers but users can use `LOG_LEVEL.${level}` +to specify the value instead of using numbers.* + +A decorator enables you to provide metadata for Controller methods to set the +minimum logLevel. + +### Example Usage + +```ts +import { + LogLevelMixin, + LogComponent, + LOG_LEVEL, + log +} from 'loopback4-example-log-extension'; +// Other imports ... + +class LogApp extends LogLevelMixin(Application) { + constructor() { + super({ + components: [RestComponent, LogComponent], + logLevel: LOG_LEVEL.ERROR, + controllers: [MyController] + }); + }; +} + +class MyController { + @log(LOG_LEVEL.WARN) + @get('/') + hello() { + return 'Hello LoopBack'; + } + + @log(LOG_LEVEL.ERROR) + @get('/name') + helloName() { + return 'Hello Name' + } +} +``` + +## Tutorial + +Install `@loopback/cli` by running `npm i -g @loopback/cli`. + +Initialize your new extension project as follows: +`lb4 extension` + +- Project name: `loopback4-example-log-extension` +- Project description: `An example extension project for LoopBack 4` +- Project root directory: `(loopback4-example-log-extension)` +- Component class name: `LogComponent` +- Select project build settings: `Enable tslint, Enable prettier, Enable mocha, Enable loopbackBuild` + +Now you can write the extension as follows: + +### `/src/keys.ts` +Define `Binding` keys here for the component as well as any constants for the +user (for this extension that'll be the logLevel `enum`). + +```ts +export namespace EXAMPLE_LOG_BINDINGS { + export const METADATA = 'example.log.metadata'; + export const APP_LOG_LEVEL = 'example.log.level'; + export const TIMER = 'example.log.timer'; + export const LOG_ACTION = 'example.log.action'; +} + +export enum LOG_LEVEL { + DEBUG, + INFO, + WARN, + ERROR, + OFF, +} +``` + +### `src/types.ts` +Define TypeScript type definitions / interfaces for complex types and functions here. + +```ts +import {ParsedRequest, OperationArgs} from '@loopback/rest'; + +export interface LogFn { + ( + req: ParsedRequest, + args: OperationArgs, + result: any, + startTime?: HighResTime, + ): Promise; + + startTimer(): HighResTime; +} + +export type LevelMetadata = {level: number}; +export type HighResTime = [number, number]; // [seconds, nanoseconds] +export type TimerFn = (start?: HighResTime) => HighResTime; +``` + +### `src/decorators/log.decorator.ts` +Extension users can use decorators to provide "hints" (or metadata) for our +component. These "hints" allow the extension to modify behaviour accordingly. + +For this extension, the decorator marks which controller methods should be +logged (and optionally at which level they should be logged). +`Reflector` from `@loopback/context` is used to store and retrieve the metadata +by the extension. + +```ts +import {LOG_LEVEL, EXAMPLE_LOG_BINDINGS} from '../keys'; +import {Constructor, Reflector} from '@loopback/context'; +import {LevelMetadata} from '../types'; + +export function log(level?: number) { + return function(target: Object, methodName: string): void { + if (level === undefined) level = LOG_LEVEL.WARN; + Reflector.defineMetadata( + EXAMPLE_LOG_BINDINGS.METADATA, + {level}, + target, + methodName, + ); + }; +} + +export function getLogMetadata( + controllerClass: Constructor<{}>, + methodName: string, +): LevelMetadata { + return Reflector.getMetadata( + EXAMPLE_LOG_BINDINGS.METADATA, + controllerClass.prototype, + methodName, + ); +} +``` + +### `src/mixins/log-level.mixin.ts` +Extension users must set an app wide log level at or above which the decorated +controller methods will be logged. A user can do so by binding the level to +`example.log.level` but this can be a hassle. + +A mixin makes it easier for the user to set the application wide log level by +providing it via `ApplicationOptions` or using a helper method `app.logLevel(level: number)`. + +```ts +import {Constructor} from '@loopback/context'; +import {EXAMPLE_LOG_BINDINGS} from '../keys'; + +export function LogLevelMixin>(superClass: T) { + return class extends superClass { + constructor(...args: any[]) { + super(...args); + if (!this.options) this.options = {}; + + if (this.options.logLevel) { + this.logLevel(this.options.logLevel); + } + } + + logLevel(level: number) { + this.bind(EXAMPLE_LOG_BINDINGS.APP_LOG_LEVEL).to(level); + } + }; +} +``` + +### Providers +A Providers is a class that returns a `value()` function that can be invoked by +LoopBack 4. + +### `src/providers/timer.provider.ts` +A timer than can be used to time the function that is being logged. + +```ts +import {Provider} from '@loopback/context'; +import {TimerFn, HighResTime} from '../types'; + +export class TimerProvider implements Provider { + constructor() {} + value(): TimerFn { + return (start?: HighResTime): HighResTime => { + if (!start) return process.hrtime(); + return process.hrtime(start); + }; + } +} +``` + +### `src/providers/log-level.provider.ts` +A provider can set the default binding value for `example.log.level` so it's +easier to get started with the extension. User's can override the value by +binding a new value or using the mixin. + +```ts +import {Provider} from '@loopback/context'; +import {LOG_LEVEL} from '../keys'; + +export class LogLevelProvider implements Provider { + constructor() {} + value(): number { + return LOG_LEVEL.WARN; + } +} +``` + +### `src/providers/log-action.provider.ts` +This will be the most important provider for the extension as it is responsible +for actually logging the request. The extension will retrieve the metadata +stored by the `@log()` decorator using the controller and method name. +Since bindings are resolved at runtime and these values change with each request, +`inject.getter()` must be used to get a function capable of resolving the value +when called. The action provider will look as follows: + +```ts +import {inject, Provider, Constructor, Getter} from '@loopback/context'; +import {CoreBindings} from '@loopback/core'; +import {OperationArgs, ParsedRequest} from '@loopback/rest'; +import {getLogMetadata} from '../decorators/log.decorator'; +import {EXAMPLE_LOG_BINDINGS, LOG_LEVEL} from '../keys'; +import {LogFn, TimerFn, HighResTime, LevelMetadata} from '../types'; +import chalk from 'chalk'; + +export class LogActionProvider implements Provider { + constructor( + @inject.getter(CoreBindings.CONTROLLER_CLASS) + private readonly getController: Getter>, + @inject.getter(CoreBindings.CONTROLLER_METHOD_NAME) + private readonly getMethod: Getter, + @inject(EXAMPLE_LOG_BINDINGS.APP_LOG_LEVEL) + private readonly logLevel: number, + @inject(EXAMPLE_LOG_BINDINGS.TIMER) public timer: TimerFn, + ) {} + + value(): LogFn { + const fn = (( + req: ParsedRequest, + args: OperationArgs, + result: any, + start?: HighResTime, + ) => { + return this.action(req, args, result, start); + }); + + fn.startTimer = () => { + return this.timer(); + }; + + return fn; + } + + private async action( + req: ParsedRequest, + args: OperationArgs, + result: any, + start?: HighResTime, + ): Promise { + const controllerClass = await this.getController(); + const methodName: string = await this.getMethod(); + const metadata: LevelMetadata = getLogMetadata(controllerClass, methodName); + const level: number | undefined = metadata ? metadata.level : undefined; + + if ( + level !== undefined && + this.logLevel !== LOG_LEVEL.OFF && + level >= this.logLevel && + level !== LOG_LEVEL.OFF + ) { + if (!args) args = []; + let log = `${req.url} :: ${controllerClass.name}.`; + log += `${methodName}(${args.join(', ')}) => `; + + if (typeof result === 'object') log += JSON.stringify(result); + else log += result; + + if (start) { + const timeDiff: HighResTime = this.timer(start); + const time: number = + timeDiff[0] * 1000 + Math.round(timeDiff[1] * 1e-4) / 100; + log = `${time}ms: ${log}`; + } + + switch (level) { + case LOG_LEVEL.DEBUG: + console.log(chalk.white(`DEBUG: ${log}`)); + break; + case LOG_LEVEL.INFO: + console.log(chalk.green(`INFO: ${log}`)); + break; + case LOG_LEVEL.WARN: + console.log(chalk.yellow(`WARN: ${log}`)); + break; + case LOG_LEVEL.ERROR: + console.log(chalk.red(`ERROR: ${log}`)); + break; + } + } + } +} +``` + +### `src/index.ts` +Export all the files to ensure a user can import the necessary components. + +```ts +export * from './decorators/log.decorator'; +export * from './mixins/log-level.mixin'; +export * from './providers/log-action.provider'; +export * from './providers/log-level.provider'; +export * from './providers/timer.provider'; +export * from './component'; +export * from './types'; +export * from './keys'; +``` + +### `src/component.ts` +Package the providers in the component to their appropriate `Binding` keys so +they are automatically bound when a user adds the component to their application. + +```ts +import {EXAMPLE_LOG_BINDINGS} from './keys'; +import {Component, ProviderMap} from '@loopback/core'; +import {TimerProvider, LogActionProvider, LogLevelProvider} from './'; + +export class LogComponent implements Component { + providers?: ProviderMap = { + [EXAMPLE_LOG_BINDINGS.TIMER]: TimerProvider, + [EXAMPLE_LOG_BINDINGS.LOG_ACTION]: LogActionProvider, + [EXAMPLE_LOG_BINDINGS.APP_LOG_LEVEL]: LogLevelProvider, + }; +} +``` + +## Testing + +Tests should be written to ensure the behaviour implemented is correct and +future modifications don't break this expected behavior *(unless it's +intentional in which case the tests should be updated as well)*. + +Take a look at the test folder to see the variety of tests written for this +extension. There are unit tests to test functionality of individual functions +as well as an extension acceptance test which tests the entire extension as a +whole (everything working together). + +## License + +MIT License diff --git a/index.ts b/index.ts index d283034..6de3de5 100644 --- a/index.ts +++ b/index.ts @@ -3,4 +3,4 @@ // This file is licensed under the MIT License. // License text available at https://opensource.org/licenses/MIT -// export * from './src'; +export * from './src'; diff --git a/package.json b/package.json index 3fb0a2d..876102b 100644 --- a/package.json +++ b/package.json @@ -1,8 +1,11 @@ { "name": "loopback4-example-log-extension", "version": "1.0.0", - "description": "An example extension project for LoopBack Next", + "description": "An example extension project for LoopBack 4", "main": "index.js", + "engines": { + "node": ">=8" + }, "scripts": { "build": "lb-tsc", "build:watch": "lb-tsc --watch", @@ -23,12 +26,7 @@ "type": "git", "url": "git+https://github.com/strongloop/loopback4-example-log-extension.git" }, - "keywords": [ - "loopback4", - "lb4ext", - "typescript", - "loopback-extension" - ], + "keywords": ["loopback", "loopback-extension"], "license": "MIT", "bugs": { "url": "https://github.com/strongloop/loopback4-example-log-extension/issues" @@ -36,6 +34,12 @@ "homepage": "https://github.com/strongloop/loopback4-example-log-extension#readme", "devDependencies": { "@loopback/build": "^4.0.0-alpha.3", - "@loopback/testlab": "^4.0.0-alpha.13" + "@loopback/testlab": "^4.0.0-alpha.12" + }, + "dependencies": { + "@loopback/context": "^4.0.0-alpha.17", + "@loopback/core": "^4.0.0-alpha.19", + "@loopback/rest": "^4.0.0-alpha.6", + "chalk": "^2.3.0" } } diff --git a/src/component.ts b/src/component.ts new file mode 100644 index 0000000..de6d000 --- /dev/null +++ b/src/component.ts @@ -0,0 +1,16 @@ +// Copyright IBM Corp. 2017. All Rights Reserved. +// Node module: loopback4-example-log-extension +// This file is licensed under the MIT License. +// License text available at https://opensource.org/licenses/MIT + +import {EXAMPLE_LOG_BINDINGS} from './keys'; +import {Component, ProviderMap} from '@loopback/core'; +import {TimerProvider, LogActionProvider, LogLevelProvider} from './'; + +export class LogComponent implements Component { + providers?: ProviderMap = { + [EXAMPLE_LOG_BINDINGS.TIMER]: TimerProvider, + [EXAMPLE_LOG_BINDINGS.LOG_ACTION]: LogActionProvider, + [EXAMPLE_LOG_BINDINGS.APP_LOG_LEVEL]: LogLevelProvider, + }; +} diff --git a/src/decorators/log.decorator.ts b/src/decorators/log.decorator.ts new file mode 100644 index 0000000..aa1c9f2 --- /dev/null +++ b/src/decorators/log.decorator.ts @@ -0,0 +1,44 @@ +// Copyright IBM Corp. 2017. All Rights Reserved. +// Node module: loopback4-example-log-extension +// This file is licensed under the MIT License. +// License text available at https://opensource.org/licenses/MIT + +import {LOG_LEVEL, EXAMPLE_LOG_BINDINGS} from '../keys'; +import {Constructor, Reflector} from '@loopback/context'; +import {LevelMetadata} from '../types'; + +/** + * Mark a controller method as requiring logging (input, output & timing) + * if it is set at or greater than Application LogLevel. + * LOG_LEVEL.DEBUG < LOG_LEVEL.INFO < LOG_LEVEL.WARN < LOG_LEVEL.ERROR < LOG_LEVEL.OFF + * + * @param level The Log Level at or above it should log + */ +export function log(level?: number) { + return function(target: Object, methodName: string): void { + if (level === undefined) level = LOG_LEVEL.WARN; + Reflector.defineMetadata( + EXAMPLE_LOG_BINDINGS.METADATA, + {level}, + target, + methodName, + ); + }; +} + +/** + * Fetch log level stored by `@log` decorator. + * + * @param controllerClass Target controller + * @param methodName Target method + */ +export function getLogMetadata( + controllerClass: Constructor<{}>, + methodName: string, +): LevelMetadata { + return Reflector.getMetadata( + EXAMPLE_LOG_BINDINGS.METADATA, + controllerClass.prototype, + methodName, + ); +} diff --git a/src/index.ts b/src/index.ts new file mode 100644 index 0000000..f03f113 --- /dev/null +++ b/src/index.ts @@ -0,0 +1,13 @@ +// Copyright IBM Corp. 2017. All Rights Reserved. +// Node module: loopback4-example-log-extension +// This file is licensed under the MIT License. +// License text available at https://opensource.org/licenses/MIT + +export * from './decorators/log.decorator'; +export * from './mixins/log-level.mixin'; +export * from './providers/log-action.provider'; +export * from './providers/log-level.provider'; +export * from './providers/timer.provider'; +export * from './component'; +export * from './types'; +export * from './keys'; diff --git a/src/keys.ts b/src/keys.ts new file mode 100644 index 0000000..896afde --- /dev/null +++ b/src/keys.ts @@ -0,0 +1,25 @@ +// Copyright IBM Corp. 2017. All Rights Reserved. +// Node module: loopback4-example-log-extension +// This file is licensed under the MIT License. +// License text available at https://opensource.org/licenses/MIT + +/** + * Binding keys used by this component. + */ +export namespace EXAMPLE_LOG_BINDINGS { + export const METADATA = 'example.log.metadata'; + export const APP_LOG_LEVEL = 'example.log.level'; + export const TIMER = 'example.log.timer'; + export const LOG_ACTION = 'example.log.action'; +} + +/** + * Enum to define the supported log levels + */ +export enum LOG_LEVEL { + DEBUG, + INFO, + WARN, + ERROR, + OFF, +} diff --git a/src/mixins/log-level.mixin.ts b/src/mixins/log-level.mixin.ts new file mode 100644 index 0000000..f0e1801 --- /dev/null +++ b/src/mixins/log-level.mixin.ts @@ -0,0 +1,45 @@ +// Copyright IBM Corp. 2017. All Rights Reserved. +// Node module: loopback4-example-log-extension +// This file is licensed under the MIT License. +// License text available at https://opensource.org/licenses/MIT + +import {Constructor} from '@loopback/context'; +import {EXAMPLE_LOG_BINDINGS} from '../keys'; + +/** + * A mixin class for Application that can bind logLevel from `options`. + * Also provides .logLevel() to bind application wide logLevel. + * Functions with a log level set to logLevel or higher sill log data + * + * ```ts + * class MyApplication extends LogLevelMixin(Application) {} + * ``` + */ +// tslint:disable-next-line:no-any +export function LogLevelMixin>(superClass: T) { + return class extends superClass { + // A mixin class has to take in a type any[] argument! + // tslint:disable-next-line:no-any + constructor(...args: any[]) { + super(...args); + if (!this.options) this.options = {}; + + if (this.options.logLevel) { + this.logLevel(this.options.logLevel); + } + } + + /** + * Set minimum logLevel to be displayed. + * + * @param level The log level to set for @log decorator + * + * ```ts + * app.logLevel(LogLevel.INFO); + * ``` + */ + logLevel(level: number) { + this.bind(EXAMPLE_LOG_BINDINGS.APP_LOG_LEVEL).to(level); + } + }; +} diff --git a/src/providers/log-action.provider.ts b/src/providers/log-action.provider.ts new file mode 100644 index 0000000..a212bd8 --- /dev/null +++ b/src/providers/log-action.provider.ts @@ -0,0 +1,92 @@ +// Copyright IBM Corp. 2017. All Rights Reserved. +// Node module: loopback4-example-log-extension +// This file is licensed under the MIT License. +// License text available at https://opensource.org/licenses/MIT + +import {inject, Provider, Constructor, Getter} from '@loopback/context'; +import {CoreBindings} from '@loopback/core'; +import {OperationArgs, ParsedRequest} from '@loopback/rest'; +import {getLogMetadata} from '../decorators/log.decorator'; +import {EXAMPLE_LOG_BINDINGS, LOG_LEVEL} from '../keys'; +import {LogFn, TimerFn, HighResTime, LevelMetadata} from '../types'; +import chalk from 'chalk'; + +export class LogActionProvider implements Provider { + constructor( + @inject.getter(CoreBindings.CONTROLLER_CLASS) + private readonly getController: Getter>, + @inject.getter(CoreBindings.CONTROLLER_METHOD_NAME) + private readonly getMethod: Getter, + @inject(EXAMPLE_LOG_BINDINGS.APP_LOG_LEVEL) + private readonly logLevel: number, + @inject(EXAMPLE_LOG_BINDINGS.TIMER) public timer: TimerFn, + ) {} + + value(): LogFn { + const fn = (( + req: ParsedRequest, + args: OperationArgs, + // tslint:disable-next-line:no-any + result: any, + start?: HighResTime, + ) => { + return this.action(req, args, result, start); + }); + + fn.startTimer = () => { + return this.timer(); + }; + + return fn; + } + + private async action( + req: ParsedRequest, + args: OperationArgs, + // tslint:disable-next-line:no-any + result: any, + start?: HighResTime, + ): Promise { + const controllerClass = await this.getController(); + const methodName: string = await this.getMethod(); + + const metadata: LevelMetadata = getLogMetadata(controllerClass, methodName); + const level: number | undefined = metadata ? metadata.level : undefined; + + if ( + level !== undefined && + this.logLevel !== LOG_LEVEL.OFF && + level >= this.logLevel && + level !== LOG_LEVEL.OFF + ) { + if (!args) args = []; + let log = `${req.url} :: ${controllerClass.name}.`; + log += `${methodName}(${args.join(', ')}) => `; + + if (typeof result === 'object') log += JSON.stringify(result); + else log += result; + + if (start) { + const timeDiff: HighResTime = this.timer(start); + const time: number = + timeDiff[0] * 1000 + Math.round(timeDiff[1] * 1e-4) / 100; + log = `${time}ms: ${log}`; + } + + switch (level) { + case LOG_LEVEL.DEBUG: + console.log(chalk.white(`DEBUG: ${log}`)); + break; + case LOG_LEVEL.INFO: + console.log(chalk.green(`INFO: ${log}`)); + break; + case LOG_LEVEL.WARN: + console.log(chalk.yellow(`WARN: ${log}`)); + break; + case LOG_LEVEL.ERROR: + console.log(chalk.red(`ERROR: ${log}`)); + break; + } + } + } +} diff --git a/src/providers/log-level.provider.ts b/src/providers/log-level.provider.ts new file mode 100644 index 0000000..fdbe1d5 --- /dev/null +++ b/src/providers/log-level.provider.ts @@ -0,0 +1,15 @@ +// Copyright IBM Corp. 2017. All Rights Reserved. +// Node module: loopback4-example-log-extension +// This file is licensed under the MIT License. +// License text available at https://opensource.org/licenses/MIT + +import {Provider} from '@loopback/context'; +import {LOG_LEVEL} from '../keys'; + +export class LogLevelProvider implements Provider { + constructor() {} + + value(): number { + return LOG_LEVEL.WARN; + } +} diff --git a/src/providers/timer.provider.ts b/src/providers/timer.provider.ts new file mode 100644 index 0000000..02be863 --- /dev/null +++ b/src/providers/timer.provider.ts @@ -0,0 +1,18 @@ +// Copyright IBM Corp. 2017. All Rights Reserved. +// Node module: loopback4-example-log-extension +// This file is licensed under the MIT License. +// License text available at https://opensource.org/licenses/MIT + +import {Provider} from '@loopback/context'; +import {TimerFn, HighResTime} from '../types'; + +export class TimerProvider implements Provider { + constructor() {} + + value(): TimerFn { + return (start?: HighResTime): HighResTime => { + if (!start) return process.hrtime(); + return process.hrtime(start); + }; + } +} diff --git a/src/types.ts b/src/types.ts new file mode 100644 index 0000000..7f1a5a7 --- /dev/null +++ b/src/types.ts @@ -0,0 +1,26 @@ +// Copyright IBM Corp. 2017. All Rights Reserved. +// Node module: loopback4-example-log-extension +// This file is licensed under the MIT License. +// License text available at https://opensource.org/licenses/MIT + +// Types and interfaces exposed by the extension go here + +import {ParsedRequest, OperationArgs} from '@loopback/rest'; + +export interface LogFn { + ( + req: ParsedRequest, + args: OperationArgs, + // tslint:disable-next-line:no-any + result: any, + startTime?: HighResTime, + ): Promise; + + startTimer(): HighResTime; +} + +export type LevelMetadata = {level: number}; + +export type HighResTime = [number, number]; // [seconds, nanoseconds] + +export type TimerFn = (start?: HighResTime) => HighResTime; diff --git a/test/acceptance/log.extension.acceptance.ts b/test/acceptance/log.extension.acceptance.ts new file mode 100644 index 0000000..4501cde --- /dev/null +++ b/test/acceptance/log.extension.acceptance.ts @@ -0,0 +1,327 @@ +// Copyright IBM Corp. 2017. All Rights Reserved. +// Node module: loopback4-example-log-extension +// This file is licensed under the MIT License. +// License text available at https://opensource.org/licenses/MIT + +import {Application} from '@loopback/core'; +import { + RestComponent, + RestServer, + get, + param, + SequenceHandler, + RestBindings, + FindRoute, + ParseParams, + InvokeMethod, + Send, + Reject, + ParsedRequest, + ServerResponse, +} from '@loopback/rest'; +import { + LogComponent, + LogLevelMixin, + LOG_LEVEL, + log, + EXAMPLE_LOG_BINDINGS, + LogFn, + HighResTime, +} from '../..'; +import { + sinon, + SinonSpy, + Client, + createClientForHandler, + expect, +} from '@loopback/testlab'; +import {Context, inject} from '@loopback/context'; +import chalk from 'chalk'; + +const SequenceActions = RestBindings.SequenceActions; + +describe('log extension acceptance test', () => { + let app: LogApp; + let server: RestServer; + let spy: SinonSpy; + + class LogApp extends LogLevelMixin(Application) {} + + const debugMatch: string = chalk.white( + 'DEBUG: /debug :: MyController.debug() => debug called', + ); + const infoMatch: string = chalk.green( + 'INFO: /info :: MyController.info() => info called', + ); + const warnMatch: string = chalk.yellow( + 'WARN: /warn :: MyController.warn() => warn called', + ); + const errorMatch: string = chalk.red( + 'ERROR: /error :: MyController.error() => error called', + ); + const nameMatch: string = chalk.yellow( + 'WARN: /?name=test :: MyController.hello(test) => hello test', + ); + + beforeEach(createApp); + beforeEach(createController); + beforeEach(createSequence); + beforeEach(createConsoleSpy); + + afterEach(restoreConsoleSpy); + + it('logs information at DEBUG or higher', async () => { + setAppLogToDebug(); + const client: Client = createClientForHandler(server.handleHttp); + + await client.get('/nolog').expect(200, 'nolog called'); + expect(spy.called).to.be.False(); + + await client.get('/off').expect(200, 'off called'); + expect(spy.called).to.be.False(); + + await client.get('/debug').expect(200, 'debug called'); + sinon.assert.calledWith(spy, debugMatch); + + await client.get('/info').expect(200, 'info called'); + sinon.assert.calledWith(spy, infoMatch); + + await client.get('/warn').expect(200, 'warn called'); + sinon.assert.calledWith(spy, warnMatch); + + await client.get('/error').expect(200, 'error called'); + sinon.assert.calledWith(spy, errorMatch); + + await client.get('/?name=test').expect(200, 'hello test'); + sinon.assert.calledWith(spy, nameMatch); + }); + + it('logs information at INFO or higher', async () => { + setAppLogToInfo(); + const client: Client = createClientForHandler(server.handleHttp); + + await client.get('/nolog').expect(200, 'nolog called'); + expect(spy.called).to.be.False(); + + await client.get('/off').expect(200, 'off called'); + expect(spy.called).to.be.False(); + + await client.get('/debug').expect(200, 'debug called'); + expect(spy.called).to.be.False(); + + await client.get('/info').expect(200, 'info called'); + sinon.assert.calledWith(spy, infoMatch); + + await client.get('/warn').expect(200, 'warn called'); + sinon.assert.calledWith(spy, warnMatch); + + await client.get('/error').expect(200, 'error called'); + sinon.assert.calledWith(spy, errorMatch); + + await client.get('/?name=test').expect(200, 'hello test'); + sinon.assert.calledWith(spy, nameMatch); + }); + + it('logs information at WARN or higher', async () => { + setAppLogToWarn(); + const client: Client = createClientForHandler(server.handleHttp); + + await client.get('/nolog').expect(200, 'nolog called'); + expect(spy.called).to.be.False(); + + await client.get('/off').expect(200, 'off called'); + expect(spy.called).to.be.False(); + + await client.get('/debug').expect(200, 'debug called'); + expect(spy.called).to.be.False(); + + await client.get('/info').expect(200, 'info called'); + expect(spy.called).to.be.False(); + + await client.get('/warn').expect(200, 'warn called'); + sinon.assert.calledWith(spy, warnMatch); + + await client.get('/error').expect(200, 'error called'); + sinon.assert.calledWith(spy, errorMatch); + + await client.get('/?name=test').expect(200, 'hello test'); + sinon.assert.calledWith(spy, nameMatch); + }); + + it('logs information at ERROR', async () => { + setAppLogToError(); + const client: Client = createClientForHandler(server.handleHttp); + + await client.get('/nolog').expect(200, 'nolog called'); + expect(spy.called).to.be.False(); + + await client.get('/off').expect(200, 'off called'); + expect(spy.called).to.be.False(); + + await client.get('/debug').expect(200, 'debug called'); + expect(spy.called).to.be.False(); + + await client.get('/info').expect(200, 'info called'); + expect(spy.called).to.be.False(); + + await client.get('/warn').expect(200, 'warn called'); + expect(spy.called).to.be.False(); + + await client.get('/?name=test').expect(200, 'hello test'); + expect(spy.called).to.be.False(); + + await client.get('/error').expect(200, 'error called'); + sinon.assert.calledWith(spy, errorMatch); + }); + + it('logs no information when logLevel is set to OFF', async () => { + setAppLogToOff(); + const client: Client = createClientForHandler(server.handleHttp); + + await client.get('/nolog').expect(200, 'nolog called'); + expect(spy.called).to.be.False(); + + await client.get('/off').expect(200, 'off called'); + expect(spy.called).to.be.False(); + + await client.get('/debug').expect(200, 'debug called'); + expect(spy.called).to.be.False(); + + await client.get('/info').expect(200, 'info called'); + expect(spy.called).to.be.False(); + + await client.get('/warn').expect(200, 'warn called'); + expect(spy.called).to.be.False(); + + await client.get('/?name=test').expect(200, 'hello test'); + expect(spy.called).to.be.False(); + + await client.get('/error').expect(200, 'error called'); + expect(spy.called).to.be.False(); + }); + + function createSequence() { + class LogSequence implements SequenceHandler { + constructor( + @inject(RestBindings.Http.CONTEXT) public ctx: Context, + @inject(SequenceActions.FIND_ROUTE) protected findRoute: FindRoute, + @inject(SequenceActions.PARSE_PARAMS) + protected parseParams: ParseParams, + @inject(SequenceActions.INVOKE_METHOD) protected invoke: InvokeMethod, + @inject(SequenceActions.SEND) protected send: Send, + @inject(SequenceActions.REJECT) protected reject: Reject, + @inject(EXAMPLE_LOG_BINDINGS.LOG_ACTION) protected logger: LogFn, + ) {} + + async handle(req: ParsedRequest, res: ServerResponse) { + // tslint:disable-next-line:no-any + let args: any = []; + // tslint:disable-next-line:no-any + let result: any; + + try { + const route = this.findRoute(req); + args = await this.parseParams(req, route); + result = await this.invoke(route, args); + this.send(res, result); + } catch (err) { + this.reject(res, req, err); + result = err; + } + + await this.logger(req, args, result); + } + } + + server.sequence(LogSequence); + } + + async function createApp() { + app = new LogApp({ + components: [RestComponent, LogComponent], + }); + + app.bind(EXAMPLE_LOG_BINDINGS.TIMER).to(timer); + server = await app.getServer(RestServer); + } + + function setAppLogToDebug() { + app.logLevel(LOG_LEVEL.DEBUG); + } + + function setAppLogToWarn() { + app.logLevel(LOG_LEVEL.WARN); + } + + function setAppLogToError() { + app.logLevel(LOG_LEVEL.ERROR); + } + + function setAppLogToInfo() { + app.logLevel(LOG_LEVEL.INFO); + } + + function setAppLogToOff() { + app.logLevel(LOG_LEVEL.OFF); + } + + function createController() { + class MyController { + @get('/debug') + @log(LOG_LEVEL.DEBUG) + debug() { + return 'debug called'; + } + + @get('/warn') + @log(LOG_LEVEL.WARN) + warn() { + return 'warn called'; + } + + @get('/info') + @log(LOG_LEVEL.INFO) + info() { + return 'info called'; + } + + @get('/error') + @log(LOG_LEVEL.ERROR) + error() { + return 'error called'; + } + + @get('/off') + @log(LOG_LEVEL.OFF) + off() { + return 'off called'; + } + + @get('/') + @log() + hello(@param.query.string('name') name: string) { + return `hello ${name}`; + } + + @get('/nolog') + nolog() { + return 'nolog called'; + } + } + + app.controller(MyController); + } + + function timer(startTime?: HighResTime): HighResTime { + if (!startTime) return [3, 3]; + return [2, 2]; + } + + function createConsoleSpy() { + spy = sinon.spy(console, 'log'); + } + + function restoreConsoleSpy() { + spy.restore(); + } +}); diff --git a/test/mocha.opts b/test/mocha.opts new file mode 100644 index 0000000..d5bd344 --- /dev/null +++ b/test/mocha.opts @@ -0,0 +1,2 @@ +--recursive +--reporter dot diff --git a/test/unit/decorators/log.decorator.unit.ts b/test/unit/decorators/log.decorator.unit.ts new file mode 100644 index 0000000..58d7518 --- /dev/null +++ b/test/unit/decorators/log.decorator.unit.ts @@ -0,0 +1,29 @@ +// Copyright IBM Corp. 2017. All Rights Reserved. +// Node module: loopback4-example-log-extension +// This file is licensed under the MIT License. +// License text available at https://opensource.org/licenses/MIT + +import {expect} from '@loopback/testlab'; +import {log, getLogMetadata, LOG_LEVEL, LevelMetadata} from '../../..'; + +describe('@log() decorator (unit)', () => { + it('sets log level for method to given value', () => { + class TestClass { + @log(LOG_LEVEL.ERROR) + test() {} + } + + const level: LevelMetadata = getLogMetadata(TestClass, 'test'); + expect(level.level).to.be.eql(LOG_LEVEL.ERROR); + }); + + it('sets log level for method to default', () => { + class TestClass { + @log() + test() {} + } + + const level: LevelMetadata = getLogMetadata(TestClass, 'test'); + expect(level.level).to.be.eql(LOG_LEVEL.WARN); + }); +}); diff --git a/test/unit/mixins/log-level.mixin.unit.ts b/test/unit/mixins/log-level.mixin.unit.ts new file mode 100644 index 0000000..83f93ca --- /dev/null +++ b/test/unit/mixins/log-level.mixin.unit.ts @@ -0,0 +1,36 @@ +// Copyright IBM Corp. 2017. All Rights Reserved. +// Node module: loopback4-example-log-extension +// This file is licensed under the MIT License. +// License text available at https://opensource.org/licenses/MIT + +import {expect} from '@loopback/testlab'; +import {Application} from '@loopback/core'; +import {LogLevelMixin, LOG_LEVEL, EXAMPLE_LOG_BINDINGS} from '../../..'; + +describe('LogLevelMixin (unit)', () => { + it('mixed class has .logLevel()', () => { + const myApp = new AppWithLogLevel(); + expect(typeof myApp.logLevel).to.be.eql('function'); + }); + + it('binds LogLevel from constructor', () => { + const myApp = new AppWithLogLevel({ + logLevel: LOG_LEVEL.ERROR, + }); + + expectLogLevelToBeBound(myApp); + }); + + it('bind logLevel from app.logLevel()', () => { + const myApp = new AppWithLogLevel(); + myApp.logLevel(LOG_LEVEL.ERROR); + expectLogLevelToBeBound(myApp); + }); + + class AppWithLogLevel extends LogLevelMixin(Application) {} + + function expectLogLevelToBeBound(myApp: Application) { + const logLevel = myApp.getSync(EXAMPLE_LOG_BINDINGS.APP_LOG_LEVEL); + expect(logLevel).to.be.eql(LOG_LEVEL.ERROR); + } +}); diff --git a/test/unit/providers/log-action.provider.unit.ts b/test/unit/providers/log-action.provider.unit.ts new file mode 100644 index 0000000..b69bf4c --- /dev/null +++ b/test/unit/providers/log-action.provider.unit.ts @@ -0,0 +1,83 @@ +// Copyright IBM Corp. 2017. All Rights Reserved. +// Node module: loopback4-example-log-extension +// This file is licensed under the MIT License. +// License text available at https://opensource.org/licenses/MIT + +import {sinon} from '@loopback/testlab'; +import {ParsedRequest} from '@loopback/rest'; +import {Context} from '@loopback/context'; +import { + LogActionProvider, + LogFn, + log, + EXAMPLE_LOG_BINDINGS, + LOG_LEVEL, + HighResTime, +} from '../../..'; +import {CoreBindings} from '@loopback/core'; +import chalk from 'chalk'; + +describe('LogActionProvider (unit)', () => { + let spy: sinon.SinonSpy; + let logger: LogFn; + const req = {url: '/test'}; + + beforeEach(createConsoleSpy); + beforeEach(getLogger); + + afterEach(restoreConsoleSpy); + + it('logs a value without a start time', async () => { + const match = chalk.red('ERROR: /test :: TestClass.test() => test message'); + + await logger(req, [], 'test message'); + sinon.assert.calledWith(spy, match); + }); + + it('logs a value with a start time', async () => { + const match = chalk.red( + 'ERROR: 100ms: /test :: TestClass.test() => test message', + ); + const startTime: HighResTime = logger.startTimer(); + + await logger(req, [], 'test message', startTime); + sinon.assert.calledWith(spy, match); + }); + + it('logs a value with args present', async () => { + const match = chalk.red( + 'ERROR: /test :: TestClass.test(test, message) => test message', + ); + + await logger(req, ['test', 'message'], 'test message'); + sinon.assert.calledWith(spy, match); + }); + + async function getLogger() { + class TestClass { + @log(LOG_LEVEL.ERROR) + test() {} + } + + const context: Context = new Context(); + context.bind(CoreBindings.CONTROLLER_CLASS).to(TestClass); + context.bind(CoreBindings.CONTROLLER_METHOD_NAME).to('test'); + context.bind(EXAMPLE_LOG_BINDINGS.APP_LOG_LEVEL).to(LOG_LEVEL.WARN); + context.bind(EXAMPLE_LOG_BINDINGS.TIMER).to(timer); + context.bind(EXAMPLE_LOG_BINDINGS.LOG_ACTION).toProvider(LogActionProvider); + logger = await context.get(EXAMPLE_LOG_BINDINGS.LOG_ACTION); + } + + function createConsoleSpy() { + spy = sinon.spy(console, 'log'); + } + + function restoreConsoleSpy() { + spy.restore(); + } + + function timer(startTime?: HighResTime): HighResTime { + if (!startTime) return [3, 3]; + else return [0, 100000002]; + } +}); diff --git a/test/unit/providers/log-level.provider.unit.ts b/test/unit/providers/log-level.provider.unit.ts new file mode 100644 index 0000000..bcf332a --- /dev/null +++ b/test/unit/providers/log-level.provider.unit.ts @@ -0,0 +1,14 @@ +// Copyright IBM Corp. 2017. All Rights Reserved. +// Node module: loopback4-extension-starter +// This file is licensed under the MIT License. +// License text available at https://opensource.org/licenses/MIT + +import {expect} from '@loopback/testlab'; +import {LogLevelProvider, LOG_LEVEL} from '../../..'; + +describe('LogLevelProvider (unit)', () => { + it('returns LOG_LEVEL.WARN as default level', () => { + const level = new LogLevelProvider().value(); + expect(level).to.be.eql(LOG_LEVEL.WARN); + }); +}); diff --git a/test/unit/providers/timer.provider.unit.ts b/test/unit/providers/timer.provider.unit.ts new file mode 100644 index 0000000..0163880 --- /dev/null +++ b/test/unit/providers/timer.provider.unit.ts @@ -0,0 +1,26 @@ +// Copyright IBM Corp. 2017. All Rights Reserved. +// Node module: loopback4-extension-starter +// This file is licensed under the MIT License. +// License text available at https://opensource.org/licenses/MIT + +import {expect} from '@loopback/testlab'; +import {TimerProvider} from '../../..'; +import {TimerFn, HighResTime} from '../../..'; + +describe('TimerProvider (unit)', () => { + it('returns current time given no start time', () => { + const timer: TimerFn = new TimerProvider().value(); + const time: HighResTime = timer(); + expect(time).to.have.lengthOf(2); + expect(time[0]).to.be.a.Number(); + expect(time[1]).to.be.a.Number(); + }); + + it('returns the time difference given a time', () => { + const timer: TimerFn = new TimerProvider().value(); + const diff: HighResTime = timer([2, 2]); + expect(diff).to.have.lengthOf(2); + expect(diff[0]).to.be.a.Number(); + expect(diff[1]).to.be.a.Number(); + }); +});