From 445c93f7555e2272107b47568c246da8b7d5465f Mon Sep 17 00:00:00 2001 From: Ninad Sheth Date: Mon, 14 Oct 2024 20:51:03 +0530 Subject: [PATCH] Fixed tests --- packages/client/src/client.js | 4 +- packages/client/test/client.test.js | 2 +- packages/logger/src/timing.js | 50 ++++++++++++++++++++---- packages/logger/test/logger.test.js | 60 +++++++++++++++++++++++++---- 4 files changed, 97 insertions(+), 19 deletions(-) diff --git a/packages/client/src/client.js b/packages/client/src/client.js index 8b6e3fd3a..987e93b83 100644 --- a/packages/client/src/client.js +++ b/packages/client/src/client.js @@ -115,7 +115,7 @@ export class PercyClient { } // Performs a GET request for an API endpoint with appropriate headers. - get(path, meta) { + get(path, meta = {}) { return logger.measure('client:get', meta.identifier, meta, () => { return request(`${this.apiUrl}/${path}`, { headers: this.headers(), @@ -456,7 +456,7 @@ export class PercyClient { // Convenience method for creating a snapshot for the active build, uploading // missing resources for the snapshot, and finalizing the snapshot. async sendSnapshot(buildId, options) { - let { meta } = options; + let { meta = {} } = options; let snapshot = await this.createSnapshot(buildId, options); meta.snapshotId = snapshot.data.id; diff --git a/packages/client/test/client.test.js b/packages/client/test/client.test.js index d039b690e..23d38d1ec 100644 --- a/packages/client/test/client.test.js +++ b/packages/client/test/client.test.js @@ -651,7 +651,7 @@ describe('PercyClient', () => { it('uploads a resource for a build', async () => { await expectAsync(client.uploadResource(123, { content: 'foo', url: 'foo/bar' })).toBeResolved(); - expect(logger.stderr).toEqual(jasmine.arrayContaining(['[percy:client] Uploading 4B resource: foo/bar...'])); + expect(logger.stderr).toEqual(jasmine.arrayContaining(['[percy:client] Uploading 4B resource: foo/bar'])); expect(api.requests['/builds/123/resources'][0].body).toEqual({ data: { diff --git a/packages/logger/src/timing.js b/packages/logger/src/timing.js index cff8713d4..a18441433 100644 --- a/packages/logger/src/timing.js +++ b/packages/logger/src/timing.js @@ -7,17 +7,19 @@ export default class TimeIt { return instance; } - async measure(name, identifier, meta, callback) { + // this function has some code repeatition as it needs to handle both sync and async + // callbacks. It handles both cases when function is marked async but there is no await + // as well as functions which have async await and sync functions - including sync + // functions which returns a promise instead. + // So we need to check if callback is returning promise or not and handle accordingly + // it always returns exact same value/promise as callback function and measures time + // correctly. + measure(name, identifier, meta, callback) { const startTime = Date.now(); let errorMsg; let errorStack; - try { - return await callback(); - } catch (e) { - errorMsg = e.message; - errorStack = e.stack; - throw e; - } finally { + + const logtime = () => { const duration = Date.now() - startTime; this.log.debug( `${name} - ${identifier} - ${duration / 1000}s`, @@ -28,6 +30,38 @@ export default class TimeIt { ...meta } ); + }; + + let wasPromise = false; + try { + let ret = callback(); + // if it returned a promise then we need to return a promise + if (ret.then !== undefined && ret.then != null) { + wasPromise = true; + return ret.catch((e) => { + return { + error: e, + errorReturnedFromMeasure: true + }; + }).then((result) => { + if (result?.errorReturnedFromMeasure) { + errorMsg = result.error.message; + errorStack = result.error.stack; + } + logtime(); + if (result?.errorReturnedFromMeasure) { + throw result.error; + } + return result; + }); + } + return ret; + } catch (e) { + errorMsg = e.message; + errorStack = e.stack; + throw e; + } finally { + if (!wasPromise) logtime(); } } } diff --git a/packages/logger/test/logger.test.js b/packages/logger/test/logger.test.js index c9345d33c..92b1a7a8b 100644 --- a/packages/logger/test/logger.test.js +++ b/packages/logger/test/logger.test.js @@ -483,38 +483,82 @@ describe('logger', () => { describe('timeit', () => { describe('measure', () => { - it('should execute callback and log duration', async () => { + it('should execute async callback and log duration', async () => { const date1 = new Date(2024, 4, 11, 13, 30, 0); const date2 = new Date(2024, 4, 11, 13, 31, 0); const meta = { abc: '123' }; // Logger internally calls Date.now, so need to mock // response for it as well. spyOn(Date, 'now').and.returnValues(date1, date1, date2, date1); - const callback = async () => { log.info('abcd'); }; + const callback = async () => { + await new Promise((res, _) => setTimeout(res, 20)); + log.info('abcd'); + return 10; + }; + + logger.loglevel('debug'); + const ret = await logger.measure('step', 'test', meta, callback); + expect(ret).toEqual(10); + expect(helpers.stdout).toEqual([ + jasmine.stringContaining(`[${colors.magenta('percy:test')}] abcd`) + ]); + expect(helpers.stderr).toEqual([ + `[${colors.magenta('percy:timer')}] step - test - 60s` + ]); + }); + + it('should execute sync callback and log duration', () => { + const date1 = new Date(2024, 4, 11, 13, 30, 0); + const date2 = new Date(2024, 4, 11, 13, 31, 0); + const meta = { abc: '123' }; + // Logger internally calls Date.now, so need to mock + // response for it as well. + spyOn(Date, 'now').and.returnValues(date1, date1, date2, date1); + const callback = () => { log.info('abcd'); return 10; }; - logger.timeit.log.loglevel('debug'); - await logger.measure('step', 'test', meta, callback); + logger.loglevel('debug'); + const ret = logger.measure('step', 'test', meta, callback); + expect(ret).toEqual(10); expect(helpers.stdout).toEqual([ - `[${colors.magenta('percy:test')}] abcd` + jasmine.stringContaining(`[${colors.magenta('percy:test')}] abcd`) ]); expect(helpers.stderr).toEqual([ `[${colors.magenta('percy:timer')}] step - test - 60s` ]); }); - it('should capture error info', async () => { + it('should capture error info in async', async () => { const meta = { abc: '123' }; const error = new Error('Error'); const callback = async () => { log.info('abcd'); throw error; }; - logger.timeit.log.loglevel('debug'); + logger.loglevel('debug'); try { await logger.measure('step', 'test1', meta, callback); } catch (e) { expect(e).toEqual(error); } expect(helpers.stdout).toEqual([ - `[${colors.magenta('percy:test')}] abcd` + jasmine.stringContaining(`[${colors.magenta('percy:test')}] abcd`) + ]); + const mlog = logger.instance.query((msg => msg.debug === 'timer'))[0]; + expect(mlog.meta.errorMsg).toEqual('Error'); + expect(mlog.meta.errorStack).toEqual(jasmine.stringContaining('Error: Error')); + }); + + it('should capture error info in sync', () => { + const meta = { abc: '123' }; + const error = new Error('Error'); + const callback = () => { log.info('abcd'); throw error; }; + + logger.loglevel('debug'); + try { + logger.measure('step', 'test1', meta, callback); + } catch (e) { + expect(e).toEqual(error); + } + expect(helpers.stdout).toEqual([ + jasmine.stringContaining(`[${colors.magenta('percy:test')}] abcd`) ]); const mlog = logger.instance.query((msg => msg.debug === 'timer'))[0]; expect(mlog.meta.errorMsg).toEqual('Error');