From 69581cbf912a1b800163cd4594ed6969749d1d2c Mon Sep 17 00:00:00 2001 From: Dan Jarvis Date: Tue, 21 Mar 2023 10:05:21 -0500 Subject: [PATCH] test(CLI Onboarding): Cover dev mode feed step (#11848) --- .../console-dev-mode-feed.js | 36 +- .../console-dev-mode-feed.test.js | 386 ++++++++++++++++++ 2 files changed, 408 insertions(+), 14 deletions(-) create mode 100644 test/unit/lib/cli/interactive-setup/console-dev-mode-feed.test.js diff --git a/lib/cli/interactive-setup/console-dev-mode-feed.js b/lib/cli/interactive-setup/console-dev-mode-feed.js index 619b8ed29a3..a2b7f6c43f1 100644 --- a/lib/cli/interactive-setup/console-dev-mode-feed.js +++ b/lib/cli/interactive-setup/console-dev-mode-feed.js @@ -71,7 +71,7 @@ const handleSocketMessage = (context) => (data) => { } process.stdout.write(`${colorize(JSON.stringify(parsedBody, null, 2), jsonColors)}\n`); } catch (error) { - process.stdout.write(chalk.grey.bold(`${str}${str.endsWith('\n') ? '' : '\n'}`)); + process.stdout.write(chalk.grey(`${str}${str.endsWith('\n') ? '' : '\n'}`)); } }; @@ -88,11 +88,11 @@ const handleSocketMessage = (context) => (data) => { ); if (verbose) { if (activity.input) { - process.stdout.write(headerChalk.bold('Input\n')); + process.stdout.write(headerChalk('Input\n')); tryPrintJSON(activity.input); } if (activity.output) { - process.stdout.write(headerChalk.bold('Output\n')); + process.stdout.write(headerChalk('Output\n')); tryPrintJSON(activity.output); } } @@ -172,17 +172,6 @@ const startDevModeFeed = async (context, devModeFeedConnection) => }, 1000 * 60 * 60 * 1.5); // Check for activity every 1.5 hours let stillWorkingTimer = createStillWorkingTimeout(); - const watchStream = (feed) => { - feed.on('message', (data) => { - // Ignore connection message - const parsedData = JSON.parse(data.toString('utf-8')); - if (!parsedData.resetThrottle) { - clearTimeout(stillWorkingTimer); - stillWorkingTimer = createStillWorkingTimeout(); - } - }); - }; - watchStream(devModeFeedConnection); const connectionRefreshTimer = setInterval(async () => { const newConnection = await connectToWebSocket({ @@ -219,6 +208,25 @@ const startDevModeFeed = async (context, devModeFeedConnection) => consoleMonitoringCounter.responses = 0; consoleMonitoringCounter.events = 0; }, 1000 * 60); // Publish every 60 seconds + + const watchStream = (feed) => { + feed.on('message', (data) => { + // Ignore connection message + const parsedData = JSON.parse(data.toString('utf-8')); + if (!parsedData.resetThrottle) { + clearTimeout(stillWorkingTimer); + stillWorkingTimer = createStillWorkingTimeout(); + } + }); + feed.on('close', () => { + // Clean up if we receive a close event + clearInterval(eventPublishTimer); + clearInterval(connectionRefreshTimer); + clearTimeout(stillWorkingTimer); + resolve(); + }); + }; + watchStream(devModeFeedConnection); }); module.exports = { diff --git a/test/unit/lib/cli/interactive-setup/console-dev-mode-feed.test.js b/test/unit/lib/cli/interactive-setup/console-dev-mode-feed.test.js new file mode 100644 index 00000000000..d500fa1dde2 --- /dev/null +++ b/test/unit/lib/cli/interactive-setup/console-dev-mode-feed.test.js @@ -0,0 +1,386 @@ +'use strict'; + +const chai = require('chai'); +const WebSocket = require('ws'); +const sinon = require('sinon'); +const sleep = require('timers-ext/promise/sleep'); +const consoleUi = require('@serverless/utils/console-ui'); +const proxyquire = require('proxyquire').noPreserveCache(); + +const { expect } = chai; +chai.use(require('chai-as-promised')); + +let step; +const originalSetInterval = setInterval; +describe('test/unit/lib/cli/interactive-setup/console-dev-mode-feed.test.js', function () { + this.timeout(1000 * 60 * 3); + const fakeOrgId = '123'; + const fakeAWSAccountId = 'account1'; + const publishFake = sinon.fake(); + const fakeRegion = 'us-east-1'; + const fakeTime = 'fakeTime'; + const consoleDevModeTargetFunctions = { + functionName: ['function1'], + accountId: [fakeAWSAccountId], + region: [fakeRegion], + }; + + const fakeBold = sinon.fake.returns(''); + const fakeGreyWriter = sinon.fake.returns(''); + const fakeJSONWriter = sinon.fake.returns(''); + const fakeErrorWriter = sinon.fake.returns(''); + let socketConnection; + let socketServer; + let timers = []; + + before(() => { + step = proxyquire('../../../../../lib/cli/interactive-setup/console-dev-mode-feed', { + '@serverless/utils/api-request': async (pathname, options) => { + if (pathname === `/api/identity/orgs/${fakeOrgId}/token`) { + return { token: 'fakeToken' }; + } + if (pathname === '/api/identity/me') { + return { userId: 'user123' }; + } + if (pathname === '/api/events/publish') { + publishFake(options); + return { success: true }; + } + throw new Error(`Unexpected pathname "${pathname}"`); + }, + '@serverless/utils/console-ui': { + omitAndSortDevModeActivity: consoleUi.omitAndSortDevModeActivity, + formatConsoleDate: () => fakeTime, + formatConsoleSpan: (span) => ({ + niceName: span.name, + }), + formatConsoleEvent: (event) => ({ + message: /\.error\./.test(event.eventName) ? 'ERROR • fake' : 'WARNING • fake', + payload: /\.error\./.test(event.eventName) ? event.tags.error : event.tags.warning, + }), + }, + '@serverless/utils/lib/auth/urls': { + devModeFeed: 'ws://localhost:9988', + }, + 'chalk': { + 'grey': fakeGreyWriter, + 'grey.bold': fakeBold, + 'hex': () => fakeErrorWriter, + }, + 'json-colorizer': fakeJSONWriter, + }); + }); + + beforeEach(() => { + timers = []; + // eslint-disable-next-line no-global-assign + setInterval = (cb) => { + timers.push(cb); + }; + }); + + afterEach(() => { + if (socketConnection) { + socketConnection.terminate(); + } + if (socketServer) { + socketServer.close(); + } + // eslint-disable-next-line no-global-assign + setInterval = originalSetInterval; + }); + + it('Should be ineffective, when not in console dev mode context', async () => { + const context = { isConsoleDevMode: false, options: {} }; + expect(await step.isApplicable(context)).to.be.false; + expect(context.inapplicabilityReasonCode).to.equal('NON_DEV_MODE_CONTEXT'); + }); + + it('Should be ineffective, when no org is selected', async () => { + const context = { isConsoleDevMode: true, options: {}, org: null }; + expect(await step.isApplicable(context)).to.be.false; + expect(context.inapplicabilityReasonCode).to.equal('UNRESOLVED_ORG'); + }); + + it('Should be ineffective, when functions are targeted', async () => { + const context = { isConsoleDevMode: true, options: {}, org: { orgId: fakeOrgId } }; + expect(await step.isApplicable(context)).to.be.false; + expect(context.inapplicabilityReasonCode).to.equal('NO_TARGET_FUNCTIONS'); + }); + + it('Should be effective and connect to websocket', async () => { + const context = { + isConsoleDevMode: true, + options: { + verbose: true, + }, + org: { orgId: fakeOrgId }, + consoleDevModeTargetFunctions, + awsAccountId: fakeAWSAccountId, + serverless: { + service: { + provider: fakeRegion, + }, + }, + }; + expect(await step.isApplicable(context)).to.be.true; + + const waitForConnection = () => + new Promise((resolve) => { + socketServer = new WebSocket.Server({ port: 9988 }); + step.run(context); + socketServer.on('connection', (ws) => { + ws.on('message', () => { + ws.send( + JSON.stringify({ message: 'filters successfully applied', resetThrottle: true }) + ); + }); + resolve(ws); + }); + }); + socketConnection = await waitForConnection(); + + /** + * Set of messages containing 👇 + * + * 1. request + * 2. JSON log + * 3. text log + * 4. JSON parsable text log + * 5. s3 span + * 6. Warning event + * 7. Error event + * 8. response + * + * It also included the aws.lambda* spans that should be ignored :) + */ + const mockMessages = [ + [ + { + body: '{"key1":"value1","key2":"value2","key3":"value3"}', + timestamp: '2023-03-20T21:26:10.790Z', + tags: { + aws: { + resourceName: 'example-dev-function1', + }, + }, + type: 'aws-lambda-request', + sequenceId: 1679347571057, + }, + ], + [ + { + name: 'aws.lambda.initialization', + timestamp: '2023-03-20T21:26:10.365Z', + tags: { + aws: { + resourceName: 'example-dev-function1', + }, + }, + type: 'span', + sequenceId: 1679347571276, + }, + ], + [ + { + body: '{"message":"Hi dev mode 👋"}\n', + severityNumber: '1', + severityText: 'INFO', + timestamp: '2023-03-20T21:26:10.802Z', + tags: { + aws: { + resourceName: 'example-dev-function1', + }, + }, + type: 'log', + sequenceId: 1679344258090, + }, + { + body: 'text log\n', + severityNumber: '1', + severityText: 'INFO', + timestamp: '2023-03-20T21:26:10.802Z', + tags: { + aws: { + resourceName: 'example-dev-function1', + }, + }, + type: 'log', + sequenceId: 1679344258091, + }, + { + body: '"hello"', + severityNumber: '1', + severityText: 'INFO', + timestamp: '2023-03-20T21:26:10.802Z', + tags: { + aws: { + resourceName: 'example-dev-function1', + }, + }, + type: 'log', + sequenceId: 1679344258091, + }, + ], + [ + { + customTags: '{}', + input: '{"Bucket":"fake-bucket"}', + name: 'aws.sdk.s3.listobjectsv2', + output: '{"message": "s3 output"}', + timestamp: '2023-03-20T21:26:10.804Z', + tags: { + aws: { + resourceName: 'example-dev-function1', + }, + }, + type: 'span', + sequenceId: 1679347571306, + }, + { + customTags: '{"foo":"bar"}', + eventName: 'telemetry.warning.generated.v1', + tags: { + aws: { + resourceName: 'example-dev-function1', + }, + warning: { + message: 'This is a warning', + stacktrace: + 'at module.exports.handler (/var/task/index.js:12:7)\nat process.processTicksAndRejections (node:internal/process/task_queues:95:5)', + type: 'WARNING_TYPE_USER', + }, + }, + timestamp: '2023-03-20T21:26:10.916Z', + type: 'event', + sequenceId: 1679347571307, + }, + { + customTags: '{"foo":"bar"}', + eventName: 'telemetry.error.generated.v1', + tags: { + aws: { + resourceName: 'example-dev-function1', + }, + error: { + message: 'Oh no!', + name: 'Error', + stacktrace: + 'at module.exports.handler (/var/task/index.js:13:20)\nat process.processTicksAndRejections (node:internal/process/task_queues:95:5)', + type: 'ERROR_TYPE_CAUGHT_USER', + }, + }, + timestamp: '2023-03-20T21:26:10.924Z', + type: 'event', + sequenceId: 1679347571308, + }, + ], + [ + { + customTags: '{}', + name: 'aws.lambda.invocation', + timestamp: '2023-03-20T21:26:10.790Z', + type: 'span', + tags: { + aws: { + resourceName: 'example-dev-function1', + }, + }, + sequenceId: 1679347572067, + }, + { + customTags: '{}', + isHistorical: false, + name: 'aws.lambda', + timestamp: '2023-03-20T21:26:10.365Z', + tags: { + aws: { + resourceName: 'example-dev-function1', + }, + }, + type: 'span', + sequenceId: 1679347572068, + }, + ], + [ + { + body: '{"response":"hello there"}', + timestamp: '2023-03-20T21:26:11.934Z', + tags: { + aws: { + resourceName: 'example-dev-function1', + }, + }, + type: 'aws-lambda-response', + sequenceId: 1679347572127, + }, + ], + ]; + + // Send all messages + for (const message of mockMessages) { + socketConnection.send(JSON.stringify(message)); + } + + // Wait for all messages to be processed + await sleep(600); + + // Publish dev mode events + await timers[1](); + + // Close connection to socket + socketConnection.terminate(); + + // Assert that each message had a header and our text log was written + expect(fakeGreyWriter.callCount).to.equal(11); + expect(fakeGreyWriter.getCall(0).args[0]).to.equal( + `${fakeTime} • example-dev-function1 • Invocation Started\n` + ); + // Plain text log message + expect(fakeGreyWriter.getCall(3).args[0]).to.equal('text log\n'); + // Empty text log message + expect(fakeGreyWriter.getCall(5).args[0]).to.equal('"hello"\n'); + expect(fakeGreyWriter.getCall(6).args[0]).to.equal( + `${fakeTime} • example-dev-function1 • Span • aws.sdk.s3.listobjectsv2\n` + ); + // Check end message is last + expect(fakeGreyWriter.getCall(10).args[0]).to.equal( + `${fakeTime} • example-dev-function1 • Invocation Ended\n` + ); + + // Assert that our first log message was processed as JSON and both the warning and error event were printed to the console + expect(fakeJSONWriter.callCount).to.equal(7); + expect(fakeJSONWriter.getCall(0).args[0]).to.equal( + `${JSON.stringify(JSON.parse(mockMessages[0][0].body), null, 2)}` + ); + expect(fakeJSONWriter.getCall(1).args[0]).to.equal( + `${JSON.stringify(JSON.parse(mockMessages[2][0].body), null, 2)}` + ); + expect(fakeJSONWriter.getCall(2).args[0]).to.equal( + `${JSON.stringify(JSON.parse(mockMessages[3][0].input), null, 2)}` + ); + expect(fakeJSONWriter.getCall(3).args[0]).to.equal( + `${JSON.stringify(JSON.parse(mockMessages[3][0].output), null, 2)}` + ); + expect(fakeJSONWriter.getCall(4).args[0]).to.equal( + `${JSON.stringify(mockMessages[3][1].tags.warning, null, 2)}` + ); + expect(fakeJSONWriter.getCall(5).args[0]).to.equal( + `${JSON.stringify(mockMessages[3][2].tags.error, null, 2)}` + ); + expect(fakeJSONWriter.getCall(5).args[1].colors.BRACE).to.equal('#FD5750'); + + // Assert that the error event was printed with the error + expect(fakeErrorWriter.callCount).to.equal(1); + expect(fakeErrorWriter.getCall(0).args[0]).to.equal( + `${fakeTime} • example-dev-function1 • ERROR • fake\n` + ); + + // Validate publish event was called + expect(publishFake.callCount).to.equal(1); + expect(publishFake.getCall(0).args[0].body.event.logBatches).to.equal(3); + expect(publishFake.getCall(0).args[0].body.event.responses).to.equal(1); + expect(publishFake.getCall(0).args[0].body.event.events).to.equal(2); + expect(publishFake.getCall(0).args[0].body.event.source).to.equal('cli:serverless'); + }); +});