[Code] Add duration for queued tasks (#31885)

x-pack/plugins/code/server/__tests__/clone_worker.ts

@@ -124,6 +124,7 @@ describe('clone_worker_tests', () => {
         url: 'https://github.com/Microsoft/TypeScript-Node-Starter.git',
       },
       options: {},
+      timestamp: 0,
     });
 
     assert.ok(newInstanceSpy.calledOnce);
@@ -160,6 +161,7 @@ describe('clone_worker_tests', () => {
           url: 'https://github.com/Microsoft/TypeScript-Node-Starter.git',
         },
         options: {},
+        timestamp: 0,
       },
       {
         uri: 'github.com/Microsoft/TypeScript-Node-Starter',
@@ -197,6 +199,7 @@ describe('clone_worker_tests', () => {
         url: 'https://github.com/Microsoft/TypeScript-Node-Starter.git',
       },
       options: {},
+      timestamp: 0,
     });
 
     // Expect EsClient index to be called to update the progress to 0.

x-pack/plugins/code/server/lib/esqueue/worker.js

@@ -20,7 +20,7 @@ function formatJobObject(job) {
     type: job._type,
     id: job._id,
     // Expose the payload of the job even when the job failed/timeout
-    payload: job._source.payload.payload,
+    ...job._source.payload,
   };
 }
 

x-pack/plugins/code/server/queue/abstract_worker.ts

@@ -25,10 +25,12 @@ export abstract class AbstractWorker implements Worker {
 
   // Assemble jobs, for now most of the job object construction should be the same.
   public createJob(payload: any, options: any): Job {
+    const timestamp = moment().valueOf();
     if (options.timeout !== undefined || options.timeout !== null) {
       return {
         payload,
         options,
+        timestamp,
       };
     } else {
       return {
@@ -37,6 +39,7 @@ export abstract class AbstractWorker implements Worker {
           ...options,
           timeout: this.getTimeoutMs(payload),
         },
+        timestamp,
       };
     }
   }
@@ -101,17 +104,29 @@ export abstract class AbstractWorker implements Worker {
   }
 
   public async onJobCompleted(job: Job, res: WorkerResult) {
-    this.log.info(`${this.id} job completed with result ${JSON.stringify(res)}`);
+    this.log.info(
+      `${this.id} job completed with result ${JSON.stringify(
+        res
+      )} in ${this.workerTaskDurationSeconds(job)} seconds.`
+    );
     return await this.updateProgress(res.uri, WorkerReservedProgress.COMPLETED);
   }
 
   public async onJobExecutionError(res: any) {
-    this.log.error(`${this.id} job execution error ${JSON.stringify(res)}.`);
+    this.log.error(
+      `${this.id} job execution error ${JSON.stringify(res)} in ${this.workerTaskDurationSeconds(
+        res.job
+      )} seconds.`
+    );
     return await this.updateProgress(res.job.payload.uri, WorkerReservedProgress.ERROR);
   }
 
   public async onJobTimeOut(res: any) {
-    this.log.error(`${this.id} job timed out ${JSON.stringify(res)}`);
+    this.log.error(
+      `${this.id} job timed out ${JSON.stringify(res)} in ${this.workerTaskDurationSeconds(
+        res.job
+      )} seconds.`
+    );
     return await this.updateProgress(res.job.payload.uri, WorkerReservedProgress.TIMEOUT);
   }
 
@@ -126,4 +141,9 @@ export abstract class AbstractWorker implements Worker {
     // Set to 1 hour by default. Override this function for sub classes if necessary.
     return moment.duration(1, 'hour').asMilliseconds();
   }
+
+  private workerTaskDurationSeconds(job: Job) {
+    const diff = moment().diff(moment(job.timestamp));
+    return moment.duration(diff).asSeconds();
+  }
 }

x-pack/plugins/code/server/queue/delete_worker.test.ts

@@ -80,6 +80,7 @@ test('Execute delete job.', async () => {
       uri: 'github.com/elastic/kibana',
     },
     options: {},
+    timestamp: 0,
   });
 
   expect(cancelIndexJobSpy.calledOnce).toBeTruthy();
@@ -115,6 +116,7 @@ test('On delete job enqueued.', async () => {
       uri: 'github.com/elastic/kibana',
     },
     options: {},
+    timestamp: 0,
   });
 
   expect(indexSpy.calledOnce).toBeTruthy();
@@ -144,6 +146,7 @@ test('On delete job completed.', async () => {
         uri: 'github.com/elastic/kibana',
       },
       options: {},
+      timestamp: 0,
     },
     {
       uri: 'github.com/elastic/kibana',

x-pack/plugins/code/server/queue/index_worker.test.ts

@@ -68,6 +68,7 @@ test('Execute index job.', async () => {
     },
     options: {},
     cancellationToken: cToken,
+    timestamp: 0,
   });
 
   expect(cancelIndexJobSpy.calledOnce).toBeTruthy();
@@ -119,6 +120,7 @@ test('Execute index job and then cancel.', async () => {
     },
     options: {},
     cancellationToken: cToken,
+    timestamp: 0,
   });
 
   // Cancel the index job.
@@ -153,6 +155,7 @@ test('On index job enqueued.', async () => {
       uri: 'github.com/elastic/kibana',
     },
     options: {},
+    timestamp: 0,
   });
 
   expect(indexSpy.calledOnce).toBeTruthy();
@@ -180,6 +183,7 @@ test('On index job completed.', async () => {
         uri: 'github.com/elastic/kibana',
       },
       options: {},
+      timestamp: 0,
     },
     {
       uri: 'github.com/elastic/kibana',

x-pack/plugins/code/server/queue/job.ts

@@ -9,5 +9,6 @@ import { CancellationToken } from '../lib/esqueue';
 export interface Job {
   payload: any;
   options: any;
+  timestamp: number;
   cancellationToken?: CancellationToken;
 }

x-pack/plugins/code/server/queue/update_worker.test.ts

@@ -53,6 +53,7 @@ test('Execute update job', async () => {
       uri: 'mockrepo',
     },
     options: {},
+    timestamp: 0,
   });
 
   expect(newInstanceSpy.calledOnce).toBeTruthy();