diff --git a/x-pack/plugins/code/server/__tests__/clone_worker.ts b/x-pack/plugins/code/server/__tests__/clone_worker.ts index d60faf39897d84..b33f8ad05be2e5 100644 --- a/x-pack/plugins/code/server/__tests__/clone_worker.ts +++ b/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. diff --git a/x-pack/plugins/code/server/lib/esqueue/worker.js b/x-pack/plugins/code/server/lib/esqueue/worker.js index 6fd6ef99dd4a49..99e53fcefee4df 100644 --- a/x-pack/plugins/code/server/lib/esqueue/worker.js +++ b/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, }; } diff --git a/x-pack/plugins/code/server/queue/abstract_worker.ts b/x-pack/plugins/code/server/queue/abstract_worker.ts index 0d9999222dc67b..e853cef36f07af 100644 --- a/x-pack/plugins/code/server/queue/abstract_worker.ts +++ b/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(); + } } diff --git a/x-pack/plugins/code/server/queue/delete_worker.test.ts b/x-pack/plugins/code/server/queue/delete_worker.test.ts index 97bb4c86de09c8..b3d56efc0a8eae 100644 --- a/x-pack/plugins/code/server/queue/delete_worker.test.ts +++ b/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', diff --git a/x-pack/plugins/code/server/queue/index_worker.test.ts b/x-pack/plugins/code/server/queue/index_worker.test.ts index 34e5e632449f4d..b19f9b287208c6 100644 --- a/x-pack/plugins/code/server/queue/index_worker.test.ts +++ b/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', diff --git a/x-pack/plugins/code/server/queue/job.ts b/x-pack/plugins/code/server/queue/job.ts index d26805e1199078..7ca328c128e659 100644 --- a/x-pack/plugins/code/server/queue/job.ts +++ b/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; } diff --git a/x-pack/plugins/code/server/queue/update_worker.test.ts b/x-pack/plugins/code/server/queue/update_worker.test.ts index 7dfed6304a0fe0..34a3fcc2295286 100644 --- a/x-pack/plugins/code/server/queue/update_worker.test.ts +++ b/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();