added logging to aid in identifying source of flakyness

gmmorris · Aug 5, 2020 · 4466a66 · 4466a66
1 parent fae3c11
commit 4466a66
Show file tree

Hide file tree

Showing 5 changed files with 47 additions and 9 deletions.
diff --git a/x-pack/plugins/alerts/server/alerts_client.ts b/x-pack/plugins/alerts/server/alerts_client.ts
@@ -386,14 +386,17 @@ export class AlertsClient {
           updateResult.scheduledTaskId &&
           !isEqual(alertSavedObject.attributes.schedule, updateResult.schedule)
         ) {
+          console.log(`UPDATING ALERT ${id} RUNS TASK ${updateResult.scheduledTaskId}`);
           this.taskManager
             .runNow(updateResult.scheduledTaskId)
             .then(() => {
+              console.log(`++++++ RUN NOW TASK ${updateResult.scheduledTaskId}`);
               this.logger.debug(
                 `Alert update has rescheduled the underlying task: ${updateResult.scheduledTaskId}`
               );
             })
             .catch((err: Error) => {
+              console.log(`------ FAILED RUN NOW TASK ${updateResult.scheduledTaskId}`);
               this.logger.error(
                 `Alert update failed to run its underlying task. TaskManager runNow failed with Error: ${err.message}`
               );

diff --git a/x-pack/plugins/task_manager/server/task_store.ts b/x-pack/plugins/task_manager/server/task_store.ts
@@ -242,6 +242,8 @@ export class TaskStore {
     claimTasksById: OwnershipClaimingOpts['claimTasksById'],
     size: OwnershipClaimingOpts['size']
   ): Promise<number> {
+    console.log(`________ markAvailableTasksAsClaimed`);
+    console.log(JSON.stringify({ claimOwnershipUntil, claimTasksById, size }));
     const queryForScheduledTasks = mustBeAllOf(
       // Either a task with idle status and runAt <= now or
       // status running or claiming with a retryAt <= now.
@@ -282,6 +284,7 @@ export class TaskStore {
         max_docs: size,
       }
     );
+    console.log(`_____updated: ${updated}`);
 
     if (apmTrans) apmTrans.end();
     return updated;
@@ -294,6 +297,8 @@ export class TaskStore {
     claimTasksById: OwnershipClaimingOpts['claimTasksById'],
     size: OwnershipClaimingOpts['size']
   ): Promise<ConcreteTaskInstance[]> {
+    console.log(`________ sweepForClaimedTasks`);
+    console.log(JSON.stringify({ claimTasksById, size }));
     const claimedTasksQuery = tasksClaimedByOwner(this.taskManagerId);
     const { docs } = await this.search({
       query:
@@ -305,6 +310,8 @@ export class TaskStore {
       seq_no_primary_term: true,
     });
 
+    console.log(`docs: ${JSON.stringify(docs)}`);
+
     return docs;
   }
 

diff --git a/x-pack/test/alerting_api_integration/common/config.ts b/x-pack/test/alerting_api_integration/common/config.ts
@@ -87,8 +87,6 @@ export function createTestConfig(name: string, options: CreateTestConfigOptions)
           '--xpack.encryptedSavedObjects.encryptionKey="wuGNaIhoMpk5sO4UBxgr3NyW1sFcLgIf"',
           `--xpack.actions.enabledActionTypes=${JSON.stringify(enabledActionTypes)}`,
           '--xpack.eventLog.logEntries=true',
-          '--xpack.task_manager.max_workers=100',
-          '--xpack.task_manager.poll_interval=1000',
           `--xpack.actions.preconfigured=${JSON.stringify({
             'my-slack1': {
               actionTypeId: '.slack',

diff --git a/...st/alerting_api_integration/common/fixtures/plugins/task_manager_fixture/server/plugin.ts b/...st/alerting_api_integration/common/fixtures/plugins/task_manager_fixture/server/plugin.ts
@@ -51,7 +51,8 @@ export class SampleTaskManagerFixturePlugin
     .toPromise();
 
   public setup(core: CoreSetup) {
-    core.http.createRouter().get(
+    const router = core.http.createRouter();
+    router.get(
       {
         path: '/api/alerting_tasks/{taskId}',
         validate: {
@@ -68,15 +69,30 @@ export class SampleTaskManagerFixturePlugin
         try {
           const taskManager = await this.taskManagerStart;
           return res.ok({
-            body: await taskManager.fetch({
-              query: taskManagerQuery(tasksForAlerting, taskByIdQuery(req.params.taskId)),
-            }),
+            body: await taskManager.get(req.params.taskId),
           });
         } catch (err) {
           return res.badRequest({ body: err });
         }
       }
     );
+
+    router.get(
+      {
+        path: `/api/ensure_tasks_index_refreshed`,
+        validate: {},
+      },
+      async function (
+        context: RequestHandlerContext,
+        req: KibanaRequest<any, any, any, any>,
+        res: KibanaResponseFactory
+      ): Promise<IKibanaResponse<any>> {
+        await core.elasticsearch.legacy.client.callAsInternalUser('indices.refresh', {
+          index: '.kibana_task_manager',
+        });
+        return res.ok({ body: {} });
+      }
+    );
   }
 
   public start(core: CoreStart, { taskManager }: SampleTaskManagerFixtureStartDeps) {

diff --git a/x-pack/test/alerting_api_integration/security_and_spaces/tests/alerting/update.ts b/x-pack/test/alerting_api_integration/security_and_spaces/tests/alerting/update.ts
@@ -28,7 +28,18 @@ export default function createUpdateTests({ getService }: FtrProviderContext) {
     return supertest
       .get(`/api/alerting_tasks/${taskId}`)
       .expect(200)
-      .then((response: SupertestResponse) => response.body);
+      .then((response) => {
+        console.log(JSON.stringify(response.body));
+        return response.body;
+      });
+  }
+
+  function ensureTasksIndexRefreshed() {
+    return supertest
+      .get(`/api/ensure_tasks_index_refreshed`)
+      .send({})
+      .expect(200)
+      .then((response) => response.body);
   }
 
   describe('update', () => {
@@ -725,12 +736,14 @@ export default function createUpdateTests({ getService }: FtrProviderContext) {
           objectRemover.add(space.id, createdAlert.id, 'alert', 'alerts');
 
           await retry.try(async () => {
-            const alertTask = (await getAlertingTaskById(createdAlert.scheduledTaskId)).docs[0];
+            const alertTask = await getAlertingTaskById(createdAlert.scheduledTaskId);
             expect(alertTask.status).to.eql('idle');
             // ensure the alert inital run has completed and it's been rescheduled to half an hour from now
             ensureDatetimeIsWithinRange(Date.parse(alertTask.runAt), 30 * 60 * 1000);
           });
 
+          await ensureTasksIndexRefreshed();
+
           const updatedData = {
             name: 'bcd',
             tags: ['bar'],
@@ -768,7 +781,8 @@ export default function createUpdateTests({ getService }: FtrProviderContext) {
             case 'space_1_all_with_restricted_fixture at space1':
               expect(response.statusCode).to.eql(200);
               await retry.try(async () => {
-                const alertTask = (await getAlertingTaskById(createdAlert.scheduledTaskId)).docs[0];
+                await ensureTasksIndexRefreshed();
+                const alertTask = await getAlertingTaskById(createdAlert.scheduledTaskId);
                 expect(alertTask.status).to.eql('idle');
                 // ensure the alert is rescheduled to a minute from now
                 ensureDatetimeIsWithinRange(Date.parse(alertTask.runAt), 60 * 1000);