From 0715d6030a8928cc21bace66581f2eaedd2cdde5 Mon Sep 17 00:00:00 2001 From: Mikhail Shustov Date: Fri, 5 Feb 2021 15:34:22 +0100 Subject: [PATCH 1/4] add timeout for stop lifecycle --- .../server/plugins/plugins_system.test.ts | 44 +++++++++++++++++++ src/core/server/plugins/plugins_system.ts | 10 ++++- 2 files changed, 53 insertions(+), 1 deletion(-) diff --git a/src/core/server/plugins/plugins_system.test.ts b/src/core/server/plugins/plugins_system.test.ts index 1b5994c40c0410..8787cf523ad078 100644 --- a/src/core/server/plugins/plugins_system.test.ts +++ b/src/core/server/plugins/plugins_system.test.ts @@ -505,3 +505,47 @@ describe('start', () => { expect(log.info).toHaveBeenCalledWith(`Starting [2] plugins: [order-1,order-0]`); }); }); + +describe('stop', () => { + beforeAll(() => { + jest.useFakeTimers(); + }); + + afterAll(() => { + jest.useRealTimers(); + }); + + it('waits for 30 sec to finish "stop" and move on to the next plugin.', async () => { + const [plugin1, plugin2] = [createPlugin('timeout-stop-1'), createPlugin('timeout-stop-2')].map( + (plugin, index) => { + jest.spyOn(plugin, 'setup').mockResolvedValue(`setup-as-${index}`); + jest.spyOn(plugin, 'start').mockResolvedValue(`started-as-${index}`); + pluginsSystem.addPlugin(plugin); + return plugin; + } + ); + + const stopSpy1 = jest + .spyOn(plugin1, 'stop') + .mockImplementationOnce(() => new Promise((resolve) => resolve)); + const stopSpy2 = jest.spyOn(plugin2, 'stop').mockImplementationOnce(() => Promise.resolve()); + + mockCreatePluginSetupContext.mockImplementation(() => ({})); + + await pluginsSystem.setupPlugins(setupDeps); + const stopPromise = pluginsSystem.stopPlugins(); + + jest.runAllTimers(); + await stopPromise; + expect(stopSpy1).toHaveBeenCalledTimes(1); + expect(stopSpy2).toHaveBeenCalledTimes(1); + + expect(loggingSystemMock.collect(logger).warn).toMatchInlineSnapshot(` + Array [ + Array [ + "\\"timeout-stop-1\\" plugin didn't finish \\"stop\\" in 30sec.", + ], + ] + `); + }); +}); diff --git a/src/core/server/plugins/plugins_system.ts b/src/core/server/plugins/plugins_system.ts index 1b5e3bbb06e71d..20295652c35f6c 100644 --- a/src/core/server/plugins/plugins_system.ts +++ b/src/core/server/plugins/plugins_system.ts @@ -159,7 +159,15 @@ export class PluginsSystem { const pluginName = this.satupPlugins.pop()!; this.log.debug(`Stopping plugin "${pluginName}"...`); - await this.plugins.get(pluginName)!.stop(); + + const result = (await Promise.race([ + this.plugins.get(pluginName)!.stop(), + new Promise((resolve) => setTimeout(() => resolve({ delayed: true }), 30 * Sec)), + ])) as { delayed?: boolean }; + + if (result?.delayed) { + this.log.warn(`"${pluginName}" plugin didn't stop in 30sec., move on to the next.`); + } } } From 9635e0d0188076406397840afca79679dfecefbc Mon Sep 17 00:00:00 2001 From: Mikhail Shustov Date: Fri, 5 Feb 2021 15:34:22 +0100 Subject: [PATCH 2/4] add timeout for stop lifecycle --- .../server/plugins/plugins_system.test.ts | 44 +++++++++++++++++++ src/core/server/plugins/plugins_system.ts | 10 ++++- 2 files changed, 53 insertions(+), 1 deletion(-) diff --git a/src/core/server/plugins/plugins_system.test.ts b/src/core/server/plugins/plugins_system.test.ts index 1b5994c40c0410..8787cf523ad078 100644 --- a/src/core/server/plugins/plugins_system.test.ts +++ b/src/core/server/plugins/plugins_system.test.ts @@ -505,3 +505,47 @@ describe('start', () => { expect(log.info).toHaveBeenCalledWith(`Starting [2] plugins: [order-1,order-0]`); }); }); + +describe('stop', () => { + beforeAll(() => { + jest.useFakeTimers(); + }); + + afterAll(() => { + jest.useRealTimers(); + }); + + it('waits for 30 sec to finish "stop" and move on to the next plugin.', async () => { + const [plugin1, plugin2] = [createPlugin('timeout-stop-1'), createPlugin('timeout-stop-2')].map( + (plugin, index) => { + jest.spyOn(plugin, 'setup').mockResolvedValue(`setup-as-${index}`); + jest.spyOn(plugin, 'start').mockResolvedValue(`started-as-${index}`); + pluginsSystem.addPlugin(plugin); + return plugin; + } + ); + + const stopSpy1 = jest + .spyOn(plugin1, 'stop') + .mockImplementationOnce(() => new Promise((resolve) => resolve)); + const stopSpy2 = jest.spyOn(plugin2, 'stop').mockImplementationOnce(() => Promise.resolve()); + + mockCreatePluginSetupContext.mockImplementation(() => ({})); + + await pluginsSystem.setupPlugins(setupDeps); + const stopPromise = pluginsSystem.stopPlugins(); + + jest.runAllTimers(); + await stopPromise; + expect(stopSpy1).toHaveBeenCalledTimes(1); + expect(stopSpy2).toHaveBeenCalledTimes(1); + + expect(loggingSystemMock.collect(logger).warn).toMatchInlineSnapshot(` + Array [ + Array [ + "\\"timeout-stop-1\\" plugin didn't finish \\"stop\\" in 30sec.", + ], + ] + `); + }); +}); diff --git a/src/core/server/plugins/plugins_system.ts b/src/core/server/plugins/plugins_system.ts index 1b5e3bbb06e71d..20295652c35f6c 100644 --- a/src/core/server/plugins/plugins_system.ts +++ b/src/core/server/plugins/plugins_system.ts @@ -159,7 +159,15 @@ export class PluginsSystem { const pluginName = this.satupPlugins.pop()!; this.log.debug(`Stopping plugin "${pluginName}"...`); - await this.plugins.get(pluginName)!.stop(); + + const result = (await Promise.race([ + this.plugins.get(pluginName)!.stop(), + new Promise((resolve) => setTimeout(() => resolve({ delayed: true }), 30 * Sec)), + ])) as { delayed?: boolean }; + + if (result?.delayed) { + this.log.warn(`"${pluginName}" plugin didn't stop in 30sec., move on to the next.`); + } } } From 9491c4e1d951fd863eb06cdae33774ac6947661a Mon Sep 17 00:00:00 2001 From: restrry Date: Fri, 5 Feb 2021 16:13:42 +0100 Subject: [PATCH 3/4] update message --- src/core/server/plugins/plugins_system.test.ts | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/core/server/plugins/plugins_system.test.ts b/src/core/server/plugins/plugins_system.test.ts index 8787cf523ad078..a900d08aaaea30 100644 --- a/src/core/server/plugins/plugins_system.test.ts +++ b/src/core/server/plugins/plugins_system.test.ts @@ -543,7 +543,7 @@ describe('stop', () => { expect(loggingSystemMock.collect(logger).warn).toMatchInlineSnapshot(` Array [ Array [ - "\\"timeout-stop-1\\" plugin didn't finish \\"stop\\" in 30sec.", + "\\"timeout-stop-1\\" plugin didn't stop in 30sec., move on to the next.", ], ] `); From 3b6cce04fca44ba1a3697192c8ed21bfcfb410f8 Mon Sep 17 00:00:00 2001 From: restrry Date: Mon, 8 Feb 2021 18:28:54 +0100 Subject: [PATCH 4/4] cleanup timeout to remove async tasks --- packages/kbn-std/src/promise.test.ts | 22 ++++++------- packages/kbn-std/src/promise.ts | 27 ++++++++++------ src/core/public/plugins/plugins_service.ts | 26 ++++++++++++---- src/core/server/plugins/plugins_system.ts | 36 +++++++++++++++------- 4 files changed, 71 insertions(+), 40 deletions(-) diff --git a/packages/kbn-std/src/promise.test.ts b/packages/kbn-std/src/promise.test.ts index f7c119acd0c7a4..bf4f3951d5850c 100644 --- a/packages/kbn-std/src/promise.test.ts +++ b/packages/kbn-std/src/promise.test.ts @@ -12,40 +12,36 @@ const delay = (ms: number, resolveValue?: any) => new Promise((resolve) => setTimeout(resolve, ms, resolveValue)); describe('withTimeout', () => { - it('resolves with a promise value if resolved in given timeout', async () => { + it('resolves with a promise value and "timedout: false" if resolved in given timeout', async () => { await expect( withTimeout({ promise: delay(10, 'value'), - timeout: 200, - errorMessage: 'error-message', + timeoutMs: 200, }) - ).resolves.toBe('value'); + ).resolves.toStrictEqual({ value: 'value', timedout: false }); }); - it('rejects with errorMessage if not resolved in given time', async () => { + it('resolves with "timedout: false" if not resolved in given time', async () => { await expect( withTimeout({ promise: delay(200, 'value'), - timeout: 10, - errorMessage: 'error-message', + timeoutMs: 10, }) - ).rejects.toMatchInlineSnapshot(`[Error: error-message]`); + ).resolves.toStrictEqual({ timedout: true }); await expect( withTimeout({ promise: new Promise((i) => i), - timeout: 10, - errorMessage: 'error-message', + timeoutMs: 10, }) - ).rejects.toMatchInlineSnapshot(`[Error: error-message]`); + ).resolves.toStrictEqual({ timedout: true }); }); it('does not swallow promise error', async () => { await expect( withTimeout({ promise: Promise.reject(new Error('from-promise')), - timeout: 10, - errorMessage: 'error-message', + timeoutMs: 10, }) ).rejects.toMatchInlineSnapshot(`[Error: from-promise]`); }); diff --git a/packages/kbn-std/src/promise.ts b/packages/kbn-std/src/promise.ts index 9d8f7703c026dc..9209c2ce372c64 100644 --- a/packages/kbn-std/src/promise.ts +++ b/packages/kbn-std/src/promise.ts @@ -6,19 +6,26 @@ * Side Public License, v 1. */ -export function withTimeout({ +export async function withTimeout({ promise, - timeout, - errorMessage, + timeoutMs, }: { promise: Promise; - timeout: number; - errorMessage: string; -}) { - return Promise.race([ - promise, - new Promise((resolve, reject) => setTimeout(() => reject(new Error(errorMessage)), timeout)), - ]) as Promise; + timeoutMs: number; +}): Promise<{ timedout: true } | { timedout: false; value: T }> { + let timeout: NodeJS.Timeout | undefined; + try { + return (await Promise.race([ + promise.then((v) => ({ value: v, timedout: false })), + new Promise((resolve) => { + timeout = setTimeout(() => resolve({ timedout: true }), timeoutMs); + }), + ])) as Promise<{ timedout: true } | { timedout: false; value: T }>; + } finally { + if (timeout !== undefined) { + clearTimeout(timeout); + } + } } export function isPromise(maybePromise: T | Promise): maybePromise is Promise { diff --git a/src/core/public/plugins/plugins_service.ts b/src/core/public/plugins/plugins_service.ts index 57fbe4cbecd12f..230a675b4cda6a 100644 --- a/src/core/public/plugins/plugins_service.ts +++ b/src/core/public/plugins/plugins_service.ts @@ -111,11 +111,18 @@ export class PluginsService implements CoreService({ promise: contractOrPromise, - timeout: 10 * Sec, - errorMessage: `Setup lifecycle of "${pluginName}" plugin wasn't completed in 10sec. Consider disabling the plugin and re-start.`, + timeoutMs: 10 * Sec, }); + + if (contractMaybe.timedout) { + throw new Error( + `Setup lifecycle of "${pluginName}" plugin wasn't completed in 10sec. Consider disabling the plugin and re-start.` + ); + } else { + contract = contractMaybe.value; + } } else { contract = contractOrPromise; } @@ -154,11 +161,18 @@ export class PluginsSystem { `Plugin ${pluginName} is using asynchronous start lifecycle. Asynchronous plugins support will be removed in a later version.` ); } - contract = await withTimeout({ + const contractMaybe = await withTimeout({ promise: contractOrPromise, - timeout: 10 * Sec, - errorMessage: `Start lifecycle of "${pluginName}" plugin wasn't completed in 10sec. Consider disabling the plugin and re-start.`, + timeoutMs: 10 * Sec, }); + + if (contractMaybe.timedout) { + throw new Error( + `Start lifecycle of "${pluginName}" plugin wasn't completed in 10sec. Consider disabling the plugin and re-start.` + ); + } else { + contract = contractMaybe.value; + } } else { contract = contractOrPromise; } @@ -182,12 +196,12 @@ export class PluginsSystem { this.log.debug(`Stopping plugin "${pluginName}"...`); - const result = (await Promise.race([ - this.plugins.get(pluginName)!.stop(), - new Promise((resolve) => setTimeout(() => resolve({ delayed: true }), 30 * Sec)), - ])) as { delayed?: boolean }; + const resultMaybe = await withTimeout({ + promise: this.plugins.get(pluginName)!.stop(), + timeoutMs: 30 * Sec, + }); - if (result?.delayed) { + if (resultMaybe?.timedout) { this.log.warn(`"${pluginName}" plugin didn't stop in 30sec., move on to the next.`); } }