kibana/x-pack/plugins/task_manager/server/polling/task_poller.test.ts
Mike Côté cb2e28d1e4
Fix task manager polling flow controls (#153491)
Fixes https://github.com/elastic/kibana/issues/151938

In this PR, I'm re-writing the Task Manager poller so it doesn't run
concurrently when timeouts occur while also fixing the issue where
polling requests would pile up when polling takes time. To support this,
I've also made the following changes:
- Removed the observable monitor and the
`xpack.task_manager.max_poll_inactivity_cycles` setting
- Make the task store `search` and `updateByQuery` functions have no
retries. This prevents the request from retrying 5x whenever a timeout
occurs, causing each call taking up to 2 1/2 minutes before Kibana sees
the error (now down to 30s each). We have polling to manage retries in
these situations.
- Switch the task poller tests to use `sinon` for faking timers
- Removing the `assertStillInSetup` checks on plugin setup. Felt like a
maintenance burden that wasn't necessary to fix with my code changes.

The main code changes are within these files (to review thoroughly so
the polling cycle doesn't suddenly stop):
- x-pack/plugins/task_manager/server/polling/task_poller.ts
- x-pack/plugins/task_manager/server/polling_lifecycle.ts (easier to
review if you disregard whitespace `?w=1`)

## To verify
1. Tasks run normally (create a rule or something that goes through task
manager regularly).
2. When the update by query takes a while, the request is cancelled
after 30s or the time manually configured.
4. When the search for claimed tasks query takes a while, the request is
cancelled after 30s or the time manually configured.

**Tips:**
<details><summary>how to slowdown search for claimed task
queries</summary>

```
diff --git a/x-pack/plugins/task_manager/server/queries/task_claiming.ts b/x-pack/plugins/task_manager/server/queries/task_claiming.ts
index 07042650a37..2caefd63672 100644
--- a/x-pack/plugins/task_manager/server/queries/task_claiming.ts
+++ b/x-pack/plugins/task_manager/server/queries/task_claiming.ts
@@ -247,7 +247,7 @@ export class TaskClaiming {
         taskTypes,
       });

-    const docs = tasksUpdated > 0 ? await this.sweepForClaimedTasks(taskTypes, size) : [];
+    const docs = await this.sweepForClaimedTasks(taskTypes, size);

     this.emitEvents(docs.map((doc) => asTaskClaimEvent(doc.id, asOk(doc))));

@@ -346,6 +346,13 @@ export class TaskClaiming {
       size,
       sort: SortByRunAtAndRetryAt,
       seq_no_primary_term: true,
+      aggs: {
+        delay: {
+          shard_delay: {
+            value: '40s',
+          },
+        },
+      },
     });

     return docs;
```
</details>

<details><summary>how to slow down update by queries</summary>
Not the cleanest way but you'll see occasional request timeouts from the
updateByQuery calls. I had more luck creating rules running every 1s.

```
diff --git a/x-pack/plugins/task_manager/server/task_store.ts b/x-pack/plugins/task_manager/server/task_store.ts
index a06ee7b918a..07aa81e5388 100644
--- a/x-pack/plugins/task_manager/server/task_store.ts
+++ b/x-pack/plugins/task_manager/server/task_store.ts
@@ -126,6 +126,7 @@ export class TaskStore {
       // Timeouts are retried and make requests timeout after (requestTimeout * (1 + maxRetries))
       // The poller doesn't need retry logic because it will try again at the next polling cycle
       maxRetries: 0,
+      requestTimeout: 900,
     });
   }

@@ -458,6 +459,7 @@ export class TaskStore {
           ignore_unavailable: true,
           refresh: true,
           conflicts: 'proceed',
+          requests_per_second: 1,
           body: {
             ...opts,
             max_docs,
```
</details>

---------

Co-authored-by: Kibana Machine <42973632+kibanamachine@users.noreply.github.com>
2023-05-03 09:33:10 -04:00

342 lines
10 KiB
TypeScript

/*
* Copyright Elasticsearch B.V. and/or licensed to Elasticsearch B.V. under one
* or more contributor license agreements. Licensed under the Elastic License
* 2.0; you may not use this file except in compliance with the Elastic License
* 2.0.
*/
import sinon from 'sinon';
import { of, BehaviorSubject } from 'rxjs';
import { none } from 'fp-ts/lib/Option';
import { createTaskPoller, PollingError, PollingErrorType } from './task_poller';
import { loggingSystemMock } from '@kbn/core/server/mocks';
import { asOk, asErr } from '../lib/result_type';
describe('TaskPoller', () => {
let clock: sinon.SinonFakeTimers;
beforeEach(() => {
clock = sinon.useFakeTimers({ toFake: ['Date', 'setTimeout', 'clearTimeout'] });
});
afterEach(() => clock.restore());
test('intializes the poller with the provided interval', async () => {
const pollInterval = 100;
const halfInterval = Math.floor(pollInterval / 2);
const work = jest.fn(async () => true);
createTaskPoller<void, boolean>({
initialPollInterval: pollInterval,
logger: loggingSystemMock.create().get(),
pollInterval$: of(pollInterval),
pollIntervalDelay$: of(0),
getCapacity: () => 1,
work,
}).start();
expect(work).toHaveBeenCalledTimes(1);
// `work` is async, we have to force a node `tick`
await new Promise((resolve) => setImmediate(resolve));
clock.tick(halfInterval);
expect(work).toHaveBeenCalledTimes(1);
clock.tick(halfInterval);
await new Promise((resolve) => setImmediate(resolve));
expect(work).toHaveBeenCalledTimes(2);
await new Promise((resolve) => setImmediate(resolve));
clock.tick(pollInterval + 10);
await new Promise((resolve) => setImmediate(resolve));
expect(work).toHaveBeenCalledTimes(3);
});
test('poller adapts to pollInterval changes', async () => {
const pollInterval = 100;
const pollInterval$ = new BehaviorSubject(pollInterval);
const work = jest.fn(async () => true);
createTaskPoller<void, boolean>({
initialPollInterval: pollInterval,
logger: loggingSystemMock.create().get(),
pollInterval$,
pollIntervalDelay$: of(0),
getCapacity: () => 1,
work,
}).start();
expect(work).toHaveBeenCalledTimes(1);
// `work` is async, we have to force a node `tick`
await new Promise((resolve) => setImmediate(resolve));
clock.tick(pollInterval);
expect(work).toHaveBeenCalledTimes(2);
pollInterval$.next(pollInterval * 2);
// `work` is async, we have to force a node `tick`
await new Promise((resolve) => setImmediate(resolve));
clock.tick(pollInterval);
expect(work).toHaveBeenCalledTimes(2);
clock.tick(pollInterval);
expect(work).toHaveBeenCalledTimes(3);
pollInterval$.next(pollInterval / 2);
// `work` is async, we have to force a node `tick`
await new Promise((resolve) => setImmediate(resolve));
clock.tick(pollInterval / 2);
expect(work).toHaveBeenCalledTimes(4);
});
test('filters interval polling on capacity', async () => {
const pollInterval = 100;
const work = jest.fn(async () => true);
let hasCapacity = true;
createTaskPoller<void, boolean>({
initialPollInterval: pollInterval,
logger: loggingSystemMock.create().get(),
pollInterval$: of(pollInterval),
pollIntervalDelay$: of(0),
work,
getCapacity: () => (hasCapacity ? 1 : 0),
}).start();
expect(work).toHaveBeenCalledTimes(1);
await new Promise((resolve) => setImmediate(resolve));
clock.tick(pollInterval);
expect(work).toHaveBeenCalledTimes(2);
await new Promise((resolve) => setImmediate(resolve));
clock.tick(pollInterval);
expect(work).toHaveBeenCalledTimes(3);
hasCapacity = false;
await new Promise((resolve) => setImmediate(resolve));
clock.tick(pollInterval);
await new Promise((resolve) => setImmediate(resolve));
clock.tick(pollInterval);
expect(work).toHaveBeenCalledTimes(3);
await new Promise((resolve) => setImmediate(resolve));
clock.tick(pollInterval);
expect(work).toHaveBeenCalledTimes(3);
await new Promise((resolve) => setImmediate(resolve));
clock.tick(pollInterval);
expect(work).toHaveBeenCalledTimes(3);
hasCapacity = true;
await new Promise((resolve) => setImmediate(resolve));
clock.tick(pollInterval);
expect(work).toHaveBeenCalledTimes(4);
await new Promise((resolve) => setImmediate(resolve));
clock.tick(pollInterval);
expect(work).toHaveBeenCalledTimes(5);
});
test('waits for work to complete before emitting the next event', async () => {
const pollInterval = 100;
const { promise: worker, resolve: resolveWorker } = createResolvablePromise();
const handler = jest.fn();
const poller = createTaskPoller<string, string[]>({
initialPollInterval: pollInterval,
logger: loggingSystemMock.create().get(),
pollInterval$: of(pollInterval),
pollIntervalDelay$: of(0),
work: async (...args) => {
await worker;
return args;
},
getCapacity: () => 5,
});
poller.events$.subscribe(handler);
poller.start();
clock.tick(pollInterval);
// work should now be in progress
clock.tick(pollInterval);
await new Promise((resolve) => setImmediate(resolve));
expect(handler).toHaveBeenCalledTimes(0);
resolveWorker({});
clock.tick(pollInterval);
await new Promise((resolve) => setImmediate(resolve));
expect(handler).toHaveBeenCalledTimes(1);
clock.tick(pollInterval);
expect(handler).toHaveBeenCalledTimes(1);
});
test('returns an error when polling for work fails', async () => {
const pollInterval = 100;
const handler = jest.fn();
const poller = createTaskPoller<string, string[]>({
initialPollInterval: pollInterval,
logger: loggingSystemMock.create().get(),
pollInterval$: of(pollInterval),
pollIntervalDelay$: of(0),
work: async (...args) => {
throw new Error('failed to work');
},
getCapacity: () => 5,
});
poller.events$.subscribe(handler);
poller.start();
clock.tick(pollInterval);
await new Promise((resolve) => setImmediate(resolve));
const expectedError = new PollingError<string>(
'Failed to poll for work: Error: failed to work',
PollingErrorType.WorkError,
none
);
expect(handler).toHaveBeenCalledWith(asErr(expectedError));
expect(handler.mock.calls[0][0].error.type).toEqual(PollingErrorType.WorkError);
});
test('continues polling after work fails', async () => {
const pollInterval = 100;
const handler = jest.fn();
let callCount = 0;
const work = jest.fn(async () => {
callCount++;
if (callCount === 2) {
throw new Error('failed to work');
}
return callCount;
});
const poller = createTaskPoller<string, number>({
initialPollInterval: pollInterval,
logger: loggingSystemMock.create().get(),
pollInterval$: of(pollInterval),
pollIntervalDelay$: of(0),
work,
getCapacity: () => 5,
});
poller.events$.subscribe(handler);
poller.start();
clock.tick(pollInterval);
await new Promise((resolve) => setImmediate(resolve));
expect(handler).toHaveBeenCalledWith(asOk(1));
clock.tick(pollInterval);
await new Promise((resolve) => setImmediate(resolve));
const expectedError = new PollingError<string>(
'Failed to poll for work: Error: failed to work',
PollingErrorType.WorkError,
none
);
expect(handler).toHaveBeenCalledWith(asErr(expectedError));
expect(handler.mock.calls[1][0].error.type).toEqual(PollingErrorType.WorkError);
expect(handler).not.toHaveBeenCalledWith(asOk(2));
clock.tick(pollInterval);
await new Promise((resolve) => setImmediate(resolve));
expect(handler).toHaveBeenCalledWith(asOk(3));
});
test(`doesn't start polling until start is called`, async () => {
const pollInterval = 100;
const work = jest.fn(async () => true);
const taskPoller = createTaskPoller<void, boolean>({
initialPollInterval: pollInterval,
logger: loggingSystemMock.create().get(),
pollInterval$: of(pollInterval),
pollIntervalDelay$: of(0),
getCapacity: () => 1,
work,
});
expect(work).toHaveBeenCalledTimes(0);
clock.tick(pollInterval);
await new Promise((resolve) => setImmediate(resolve));
expect(work).toHaveBeenCalledTimes(0);
clock.tick(pollInterval);
await new Promise((resolve) => setImmediate(resolve));
expect(work).toHaveBeenCalledTimes(0);
// Start the poller here
taskPoller.start();
await new Promise((resolve) => setImmediate(resolve));
expect(work).toHaveBeenCalledTimes(1);
clock.tick(pollInterval);
await new Promise((resolve) => setImmediate(resolve));
expect(work).toHaveBeenCalledTimes(2);
});
test(`stops polling after stop is called`, async () => {
const pollInterval = 100;
const work = jest.fn(async () => true);
const taskPoller = createTaskPoller<void, boolean>({
initialPollInterval: pollInterval,
logger: loggingSystemMock.create().get(),
pollInterval$: of(pollInterval),
pollIntervalDelay$: of(0),
getCapacity: () => 1,
work,
});
taskPoller.start();
await new Promise((resolve) => setImmediate(resolve));
expect(work).toHaveBeenCalledTimes(1);
clock.tick(pollInterval);
await new Promise((resolve) => setImmediate(resolve));
expect(work).toHaveBeenCalledTimes(2);
clock.tick(pollInterval);
await new Promise((resolve) => setImmediate(resolve));
expect(work).toHaveBeenCalledTimes(3);
// Stop the poller here
taskPoller.stop();
await new Promise((resolve) => setImmediate(resolve));
expect(work).toHaveBeenCalledTimes(3);
clock.tick(pollInterval);
await new Promise((resolve) => setImmediate(resolve));
expect(work).toHaveBeenCalledTimes(3);
clock.tick(pollInterval);
await new Promise((resolve) => setImmediate(resolve));
expect(work).toHaveBeenCalledTimes(3);
});
});
function createResolvablePromise() {
let resolve: (value: unknown) => void = () => {};
const promise = new Promise((r) => {
resolve = r;
});
// The "resolve = r;" code path is called before this
return { promise, resolve };
}