[Core] add timeout for "stop" lifecycle (#90432)

* add timeout for stop lifecycle * add timeout for stop lifecycle * update message * cleanup timeout to remove async tasks
elastic · Feb 9, 2021 · 82d1672 · 82d1672
1 parent 810e4ab
commit 82d1672
Show file tree

Hide file tree

Showing 5 changed files with 117 additions and 36 deletions.
diff --git 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
@@ -6,19 +6,26 @@
  * Side Public License, v 1.
  */
 
-export function withTimeout<T>({
+export async function withTimeout<T>({
   promise,
-  timeout,
-  errorMessage,
+  timeoutMs,
 }: {
   promise: Promise<T>;
-  timeout: number;
-  errorMessage: string;
-}) {
-  return Promise.race([
-    promise,
-    new Promise((resolve, reject) => setTimeout(() => reject(new Error(errorMessage)), timeout)),
-  ]) as Promise<T>;
+  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<T>(maybePromise: T | Promise<T>): maybePromise is Promise<T> {

diff --git 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<PluginsServiceSetup, PluginsS
           );
         }
 
-        contract = await withTimeout({
+        const contractMaybe = await withTimeout({
           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;
       }
@@ -158,11 +165,18 @@ export class PluginsService implements CoreService<PluginsServiceSetup, PluginsS
           );
         }
 
-        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;
       }

diff --git a/src/core/server/plugins/plugins_system.test.ts b/src/core/server/plugins/plugins_system.test.ts
@@ -621,3 +621,45 @@ describe('asynchronous plugins', () => {
     `);
   });
 });
+
+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.flat()).toEqual(
+      expect.arrayContaining([
+        `"timeout-stop-1" plugin didn't stop in 30sec., move on to the next.`,
+      ])
+    );
+  });
+});
diff --git a/src/core/server/plugins/plugins_system.ts b/src/core/server/plugins/plugins_system.ts
@@ -105,11 +105,18 @@ export class PluginsSystem {
             `Plugin ${pluginName} is using asynchronous setup lifecycle. Asynchronous plugins support will be removed in a later version.`
           );
         }
-        contract = await withTimeout({
+        const contractMaybe = await withTimeout<any>({
           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;
       }
@@ -181,7 +195,15 @@ export class PluginsSystem {
       const pluginName = this.satupPlugins.pop()!;
 
       this.log.debug(`Stopping plugin "${pluginName}"...`);
-      await this.plugins.get(pluginName)!.stop();
+
+      const resultMaybe = await withTimeout({
+        promise: this.plugins.get(pluginName)!.stop(),
+        timeoutMs: 30 * Sec,
+      });
+
+      if (resultMaybe?.timedout) {
+        this.log.warn(`"${pluginName}" plugin didn't stop in 30sec., move on to the next.`);
+      }
     }
   }