From 9aec1ac421724fcb3212e269cbdcfeab38271f3e Mon Sep 17 00:00:00 2001 From: Raymond Feng Date: Fri, 3 Apr 2020 10:30:33 -0700 Subject: [PATCH 1/2] feat(context): expose debug method to subclasses --- packages/context/package.json | 2 +- .../src/__tests__/unit/context.unit.ts | 64 ++++++++++++++++- packages/context/src/context.ts | 72 ++++++++++++++----- 3 files changed, 116 insertions(+), 22 deletions(-) diff --git a/packages/context/package.json b/packages/context/package.json index 80b93b470b3d..dee8fe007dc9 100644 --- a/packages/context/package.json +++ b/packages/context/package.json @@ -20,6 +20,7 @@ "dependencies": { "@loopback/metadata": "^2.0.3", "debug": "^4.1.1", + "@types/debug": "^4.1.5", "p-event": "^4.1.0", "tslib": "^1.11.1", "uuid": "^7.0.3" @@ -29,7 +30,6 @@ "@loopback/eslint-config": "^6.0.3", "@loopback/testlab": "^3.0.0", "@types/bluebird": "^3.5.30", - "@types/debug": "^4.1.5", "@types/node": "^10.17.19", "@types/uuid": "^7.0.2", "bluebird": "^3.7.2" diff --git a/packages/context/src/__tests__/unit/context.unit.ts b/packages/context/src/__tests__/unit/context.unit.ts index 984b7307ba30..09397a81dd33 100644 --- a/packages/context/src/__tests__/unit/context.unit.ts +++ b/packages/context/src/__tests__/unit/context.unit.ts @@ -4,6 +4,8 @@ // License text available at https://opensource.org/licenses/MIT import {expect} from '@loopback/testlab'; +import {Debugger} from 'debug'; +import {format} from 'util'; import { Binding, BindingCreationPolicy, @@ -44,14 +46,14 @@ describe('Context constructor', () => { it('generates uuid name if not provided', () => { const ctx = new Context(); expect(ctx.name).to.match( - /^[0-9A-F]{8}-[0-9A-F]{4}-[1][0-9A-F]{3}-[89AB][0-9A-F]{3}-[0-9A-F]{12}$/i, + /^[0-9A-F]{8}-[0-9A-F]{4}-[4][0-9A-F]{3}-[89AB][0-9A-F]{3}-[0-9A-F]{12}$/i, ); }); it('adds subclass name as the prefix', () => { const ctx = new TestContext(); expect(ctx.name).to.match( - /^TestContext-[0-9A-F]{8}-[0-9A-F]{4}-[1][0-9A-F]{3}-[89AB][0-9A-F]{3}-[0-9A-F]{12}$/i, + /^TestContext-[0-9A-F]{8}-[0-9A-F]{4}-[4][0-9A-F]{3}-[89AB][0-9A-F]{3}-[0-9A-F]{12}$/i, ); }); @@ -828,6 +830,64 @@ describe('Context', () => { }); }); + describe('debug', () => { + it('allows override of debug from subclasses', () => { + let debugOutput = ''; + const myDebug = (formatter: string, ...args: unknown[]) => { + debugOutput = format(formatter, ...args); + }; + myDebug.enabled = true; + class MyContext extends Context { + constructor() { + super('my-context'); + this._debug = myDebug as Debugger; + } + + debug(formatter: string, ...args: unknown[]) { + super.debug(formatter, ...args); + } + } + + const myCtx = new MyContext(); + myCtx.debug('%s %d', 'number of bindings', 10); + expect(debugOutput).to.eql(`[${myCtx.name}] number of bindings 10`); + }); + + it('sets up debug for subclasses with the class name', () => { + class MyContext extends Context { + constructor() { + super('my-context'); + } + + get debugFn() { + return this._debug; + } + } + + const myCtx = new MyContext(); + expect(myCtx.debugFn.namespace).to.eql('loopback:context:mycontext'); + }); + + it('allows debug namespace for subclasses', () => { + class MyContext extends Context { + constructor() { + super('my-context'); + } + + getDebugNamespace() { + return 'myapp:my-context'; + } + + get debugFn() { + return this._debug; + } + } + + const myCtx = new MyContext(); + expect(myCtx.debugFn.namespace).to.eql('myapp:my-context'); + }); + }); + describe('toJSON() and inspect()', () => { beforeEach(setupBindings); diff --git a/packages/context/src/context.ts b/packages/context/src/context.ts index 07ea6e3b4920..6aeb7d1034ed 100644 --- a/packages/context/src/context.ts +++ b/packages/context/src/context.ts @@ -3,9 +3,9 @@ // This file is licensed under the MIT License. // License text available at https://opensource.org/licenses/MIT -import debugFactory from 'debug'; +import debugFactory, {Debugger} from 'debug'; import {EventEmitter} from 'events'; -import {v1 as uuidv1} from 'uuid'; +import {v4 as uuidv4} from 'uuid'; import {Binding, BindingInspectOptions, BindingTag} from './binding'; import { ConfigurationResolver, @@ -40,8 +40,6 @@ import { ValueOrPromise, } from './value-promise'; -const debug = debugFactory('loopback:context'); - /** * Context provides an implementation of Inversion of Control (IoC) container */ @@ -76,6 +74,21 @@ export class Context extends EventEmitter { */ protected configResolver: ConfigurationResolver; + /** + * A debug function which can be overridden by subclasses. + * + * @example + * ```ts + * import debugFactory from 'debug'; + * const debug = debugFactory('loopback:context:application'); + * export class Application extends Context { + * super('application'); + * this._debug = debug; + * } + * ``` + */ + protected _debug: Debugger; + /** * Create a new context. * @@ -113,13 +126,34 @@ export class Context extends EventEmitter { this.name = name ?? this.generateName(); this.tagIndexer = new ContextTagIndexer(this); this.subscriptionManager = new ContextSubscriptionManager(this); + this._debug = debugFactory(this.getDebugNamespace()); + } + + /** + * Get the debug namespace for the context class. Subclasses can override + * this method to supply its own namespace. + * + * @example + * ```ts + * export class Application extends Context { + * super('application'); + * } + * + * protected getDebugNamespace() { + * return 'loopback:context:application'; + * } + * ``` + */ + protected getDebugNamespace() { + if (this.constructor === Context) return 'loopback:context'; + const name = this.constructor.name.toLowerCase(); + return `loopback:context:${name}`; } private generateName() { - const id = uuidv1(); - let prefix = `${this.constructor.name}-`; - if (prefix === 'Context-') prefix = ''; - return `${prefix}${id}`; + const id = uuidv4(); + if (this.constructor === Context) return id; + return `${this.constructor.name}-${id}`; } /** @@ -135,14 +169,14 @@ export class Context extends EventEmitter { * as the prefix * @param args - Arguments for the debug */ - private _debug(...args: unknown[]) { + protected debug(...args: unknown[]) { /* istanbul ignore if */ - if (!debug.enabled) return; + if (!this._debug.enabled) return; const formatter = args.shift(); if (typeof formatter === 'string') { - debug(`[%s] ${formatter}`, this.name, ...args); + this._debug(`[%s] ${formatter}`, this.name, ...args); } else { - debug('[%s] ', this.name, formatter, ...args); + this._debug('[%s] ', this.name, formatter, ...args); } } @@ -184,7 +218,7 @@ export class Context extends EventEmitter { */ add(binding: Binding): this { const key = binding.key; - this._debug('[%s] Adding binding: %s', key); + this.debug('[%s] Adding binding: %s', key); let existingBinding: Binding | undefined; const keyExists = this.registry.has(key); if (keyExists) { @@ -261,14 +295,14 @@ export class Context extends EventEmitter { }, ); if (configResolver) { - debug( + this.debug( 'Custom ConfigurationResolver is loaded from %s.', ContextBindings.CONFIGURATION_RESOLVER.toString(), ); this.configResolver = configResolver; } else { // Fallback to DefaultConfigurationResolver - debug('DefaultConfigurationResolver is used.'); + this.debug('DefaultConfigurationResolver is used.'); this.configResolver = new DefaultConfigurationResolver(this); } } @@ -340,7 +374,7 @@ export class Context extends EventEmitter { * @returns true if the binding key is found and removed from this context */ unbind(key: BindingAddress): boolean { - this._debug('Unbind %s', key); + this.debug('Unbind %s', key); key = BindingKey.validate(key); const binding = this.registry.get(key); // If not found, return `false` @@ -378,7 +412,7 @@ export class Context extends EventEmitter { * which is created per request. */ close() { - this._debug('Closing context...'); + this.debug('Closing context...'); this.subscriptionManager.close(); this.tagIndexer.close(); } @@ -577,7 +611,7 @@ export class Context extends EventEmitter { keyWithPath: BindingAddress, optionsOrSession?: ResolutionOptionsOrSession, ): Promise { - this._debug('Resolving binding: %s', keyWithPath); + this.debug('Resolving binding: %s', keyWithPath); return this.getValueOrPromise( keyWithPath, optionsOrSession, @@ -645,7 +679,7 @@ export class Context extends EventEmitter { keyWithPath: BindingAddress, optionsOrSession?: ResolutionOptionsOrSession, ): ValueType | undefined { - this._debug('Resolving binding synchronously: %s', keyWithPath); + this.debug('Resolving binding synchronously: %s', keyWithPath); const valueOrPromise = this.getValueOrPromise( keyWithPath, From c53833d4799437223f57a4c6b08e321633ce8ccd Mon Sep 17 00:00:00 2001 From: Raymond Feng Date: Thu, 2 Apr 2020 12:34:30 -0700 Subject: [PATCH 2/2] feat(core): improve application signal handler registration - only register shutdown listeners when the app starts - unregister process listeners upon explicit stop - fix the test case to clean up process listeners - improve debugging with context name prefix --- .../src/__tests__/unit/application.unit.ts | 99 +++++++++---- packages/core/src/application.ts | 130 ++++++++++++++---- 2 files changed, 180 insertions(+), 49 deletions(-) diff --git a/packages/core/src/__tests__/unit/application.unit.ts b/packages/core/src/__tests__/unit/application.unit.ts index d4f400d5e238..7c7e89db6910 100644 --- a/packages/core/src/__tests__/unit/application.unit.ts +++ b/packages/core/src/__tests__/unit/application.unit.ts @@ -16,12 +16,15 @@ import {expect} from '@loopback/testlab'; import {Application, Component, CoreBindings, CoreTags, Server} from '../..'; describe('Application', () => { - describe('controller binding', () => { - let app: Application; - class MyController {} + let app: Application; + + afterEach('clean up application', () => app.stop()); + describe('controller binding', () => { beforeEach(givenApp); + class MyController {} + it('binds a controller', () => { const binding = app.controller(MyController); expect(Array.from(binding.tagNames)).to.containEql(CoreTags.CONTROLLER); @@ -49,19 +52,13 @@ describe('Application', () => { expect(binding.scope).to.equal(BindingScope.SINGLETON); expect(findKeysByTag(app, 'controller')).to.containEql(binding.key); }); - - function givenApp() { - app = new Application(); - } }); describe('component binding', () => { - let app: Application; + beforeEach(givenApp); class MyComponent implements Component {} - beforeEach(givenApp); - it('binds a component', () => { const binding = app.component(MyComponent); expect(binding.scope).to.equal(BindingScope.SINGLETON); @@ -182,15 +179,10 @@ describe('Application', () => { expect(app.contains('foo')).to.be.true(); expect(app.getSync('foo')).to.be.eql('bar'); }); - - function givenApp() { - app = new Application(); - } }); describe('server binding', () => { - let app: Application; - beforeEach(givenApplication); + beforeEach(givenApp); it('defaults to constructor name', async () => { const binding = app.server(FakeServer); @@ -224,18 +216,13 @@ describe('Application', () => { const AnotherResult = await app.getServer(AnotherServer); expect(AnotherResult.constructor.name).to.equal(AnotherServer.name); }); - - function givenApplication() { - app = new Application(); - } }); describe('service binding', () => { - let app: Application; - class MyService {} - beforeEach(givenApp); + class MyService {} + it('binds a service', () => { const binding = app.service(MyService); expect(Array.from(binding.tagNames)).to.containEql(CoreTags.SERVICE); @@ -305,15 +292,77 @@ describe('Application', () => { expect(binding.key).to.equal('services.my-service'); expect(findKeysByTag(app, 'service')).to.containEql(binding.key); }); + }); + + describe('shutdown signal listener', () => { + beforeEach(givenApp); + + it('registers a SIGTERM listener when app starts', async () => { + const count = getListeners().length; + await app.start(); + expect(getListeners().length).to.eql(count + 1); + }); + + it('does not impact SIGTERM listener when app stops without start', async () => { + const count = getListeners().length; + await app.stop(); + expect(getListeners().length).to.eql(count); + }); - function givenApp() { - app = new Application(); + it('registers/removes a SIGTERM listener by start/stop', async () => { + await app.start(); + const count = getListeners().length; + await app.stop(); + expect(getListeners().length).to.eql(count - 1); + // Restart + await app.start(); + expect(getListeners().length).to.eql(count); + }); + + it('does not register a SIGTERM listener when app is created', async () => { + const count = getListeners().length; + // Create another application + new Application(); + expect(getListeners().length).to.eql(count); + }); + + function getListeners() { + return process.listeners('SIGTERM'); } }); function findKeysByTag(ctx: Context, tag: BindingTag | RegExp) { return ctx.findByTag(tag).map(binding => binding.key); } + + function givenApp() { + app = new Application(); + } +}); + +describe('Application constructor', () => { + it('accepts config and parent context', () => { + const ctx = new Context(); + const app = new Application({name: 'my-app'}, ctx); + expect(app.parent).to.eql(ctx); + expect(app.options).to.eql({name: 'my-app'}); + }); + + it('accepts parent context without config', () => { + const ctx = new Context(); + const app = new Application(ctx); + expect(app.parent).to.eql(ctx); + }); + + it('uses application name as the context name', () => { + const app = new Application({name: 'my-app'}); + expect(app.name).to.eql('my-app'); + }); + + it('uses Application- as the context name', () => { + const app = new Application(); + expect(app.name).to.match(/Application-/); + }); }); class FakeServer extends Context implements Server { diff --git a/packages/core/src/application.ts b/packages/core/src/application.ts index 95989342ae31..601bfaae0671 100644 --- a/packages/core/src/application.ts +++ b/packages/core/src/application.ts @@ -26,6 +26,30 @@ import {LifeCycleObserverRegistry} from './lifecycle-registry'; import {Server} from './server'; import {createServiceBinding, ServiceOptions} from './service'; const debug = debugFactory('loopback:core:application'); +const debugShutdown = debugFactory('loopback:core:application:shutdown'); +const debugWarning = debugFactory('loopback:core:application:warning'); + +/** + * A helper function to build constructor args for `Context` + * @param configOrParent - Application config or parent context + * @param parent - Parent context if the first arg is application config + */ +function buildConstructorArgs( + configOrParent?: ApplicationConfig | Context, + parent?: Context, +) { + let name: string | undefined; + let parentCtx: Context | undefined; + + if (configOrParent instanceof Context) { + parentCtx = configOrParent; + name = undefined; + } else { + parentCtx = parent; + name = configOrParent?.name; + } + return [parentCtx, name]; +} /** * Application is the container for various types of artifacts, such as @@ -39,6 +63,8 @@ export class Application extends Context implements LifeCycleObserver { * A flag to indicate that the application is being shut down */ private _isShuttingDown = false; + private _shutdownOptions: ShutdownOptions; + private _signalListener: (signal: string) => Promise; /** * State of the application @@ -81,13 +107,14 @@ export class Application extends Context implements LifeCycleObserver { constructor(config?: ApplicationConfig, parent?: Context); constructor(configOrParent?: ApplicationConfig | Context, parent?: Context) { - super( - configOrParent instanceof Context ? configOrParent : parent, - 'application', - ); + // super() has to be first statement for a constructor + super(...buildConstructorArgs(configOrParent, parent)); + + this.options = + configOrParent instanceof Context ? {} : configOrParent ?? {}; - if (configOrParent instanceof Context) configOrParent = {}; - this.options = configOrParent ?? {}; + // Configure debug + this._debug = debug; // Bind the life cycle observer registry this.bind(CoreBindings.LIFE_CYCLE_OBSERVER_REGISTRY) @@ -98,11 +125,7 @@ export class Application extends Context implements LifeCycleObserver { // Make options available to other modules as well. this.bind(CoreBindings.APPLICATION_CONFIG).to(this.options); - const shutdownConfig = this.options.shutdown ?? {}; - this.setupShutdown( - shutdownConfig.signals ?? ['SIGTERM'], - shutdownConfig.gracePeriod, - ); + this._shutdownOptions = {signals: ['SIGTERM'], ...this.options.shutdown}; } /** @@ -123,7 +146,7 @@ export class Application extends Context implements LifeCycleObserver { * ``` */ controller(controllerCtor: ControllerClass, name?: string): Binding { - debug('Adding controller %s', name ?? controllerCtor.name); + this.debug('Adding controller %s', name ?? controllerCtor.name); const binding = createBindingFromClass(controllerCtor, { name, namespace: CoreBindings.CONTROLLERS, @@ -156,7 +179,7 @@ export class Application extends Context implements LifeCycleObserver { ctor: Constructor, name?: string, ): Binding { - debug('Adding server %s', name ?? ctor.name); + this.debug('Adding server %s', name ?? ctor.name); const binding = createBindingFromClass(ctor, { name, namespace: CoreBindings.SERVERS, @@ -270,6 +293,8 @@ export class Application extends Context implements LifeCycleObserver { // No-op if it's started if (this._state === 'started') return; this.setState('starting'); + this.setupShutdown(); + const registry = await this.getLifeCycleObserverRegistry(); await registry.start(); this.setState('started'); @@ -288,6 +313,11 @@ export class Application extends Context implements LifeCycleObserver { // No-op if it's created or stopped if (this._state !== 'started') return; this.setState('stopping'); + if (!this._isShuttingDown) { + // Explicit stop is called, let's remove signal listeners to avoid + // memory leak and max listener warning + this.removeSignalListener(); + } const registry = await this.getLifeCycleObserverRegistry(); await registry.stop(); this.setState('stopped'); @@ -320,7 +350,7 @@ export class Application extends Context implements LifeCycleObserver { * ``` */ public component(componentCtor: Constructor, name?: string) { - debug('Adding component: %s', name ?? componentCtor.name); + this.debug('Adding component: %s', name ?? componentCtor.name); const binding = createBindingFromClass(componentCtor, { name, namespace: CoreBindings.COMPONENTS, @@ -356,7 +386,7 @@ export class Application extends Context implements LifeCycleObserver { ctor: Constructor, name?: string, ): Binding { - debug('Adding life cycle observer %s', name ?? ctor.name); + this.debug('Adding life cycle observer %s', name ?? ctor.name); const binding = createBindingFromClass(ctor, { name, namespace: CoreBindings.LIFE_CYCLE_OBSERVERS, @@ -421,17 +451,24 @@ export class Application extends Context implements LifeCycleObserver { /** * Set up signals that are captured to shutdown the application - * @param signals - An array of signals to be trapped - * @param gracePeriod - A grace period in ms before forced exit */ - protected setupShutdown(signals: NodeJS.Signals[], gracePeriod?: number) { - const cleanup = async (signal: string) => { + protected setupShutdown() { + if (this._signalListener != null) { + this.registerSignalListener(); + return this._signalListener; + } + const gracePeriod = this._shutdownOptions.gracePeriod; + this._signalListener = async (signal: string) => { const kill = () => { - // eslint-disable-next-line @typescript-eslint/no-misused-promises - signals.forEach(sig => process.removeListener(sig, cleanup)); + this.removeSignalListener(); process.kill(process.pid, signal); }; - debug('Signal %s received for process %d', signal, process.pid); + debugShutdown( + '[%s] Signal %s received for process %d', + this.name, + signal, + process.pid, + ); if (!this._isShuttingDown) { this._isShuttingDown = true; let timer; @@ -446,8 +483,49 @@ export class Application extends Context implements LifeCycleObserver { } } }; - // eslint-disable-next-line @typescript-eslint/no-misused-promises - signals.forEach(sig => process.on(sig, cleanup)); + this.registerSignalListener(); + return this._signalListener; + } + + private registerSignalListener() { + const {signals = []} = this._shutdownOptions; + debugShutdown( + '[%s] Registering signal listeners on the process %d', + this.name, + process.pid, + signals, + ); + signals.forEach(sig => { + if (process.getMaxListeners() <= process.listenerCount(sig)) { + if (debugWarning.enabled) { + debugWarning( + '[%s] %d %s listeners are added to process %d', + this.name, + process.listenerCount(sig), + sig, + process.pid, + new Error('MaxListenersExceededWarning'), + ); + } + } + // eslint-disable-next-line @typescript-eslint/no-misused-promises + process.on(sig, this._signalListener); + }); + } + + private removeSignalListener() { + if (this._signalListener == null) return; + const {signals = []} = this._shutdownOptions; + debugShutdown( + '[%s] Removing signal listeners on the process %d', + this.name, + process.pid, + signals, + ); + signals.forEach(sig => + // eslint-disable-next-line @typescript-eslint/no-misused-promises + process.removeListener(sig, this._signalListener), + ); } } @@ -470,6 +548,10 @@ export type ShutdownOptions = { * Configuration for application */ export interface ApplicationConfig { + /** + * Name of the application context + */ + name?: string; /** * Configuration for signals that shut down the application */