Added debug output (#49)

* Added debug output Resolves #47 * Fix name of utils mocks in unit tests
dark-mechanicum · Jul 22, 2022 · ca2868d · ca2868d
1 parent bc7f659
commit ca2868d
Show file tree

Hide file tree

Showing 8 changed files with 192 additions and 12 deletions.
diff --git a/__tests__/src/codebuildjob/CodeBuildJob.ts b/__tests__/src/codebuildjob/CodeBuildJob.ts
@@ -5,6 +5,10 @@ const mocks = {
   actionsCoreInfo: jest.fn().mockName('Mock: "@actions/core".info()'),
   actionsCoreSetFailed: jest.fn().mockName('Mock: "@actions/core".setFailed()'),
   actionsCoreSetOutput: jest.fn().mockName('Mock: "@actions/core".setOutput()'),
+  actionsCoreDebug: jest.fn().mockName('Mock: "@actions/core".debug()'),
+  actionsCoreNotice: jest.fn().mockName('Mock: "@actions/core".notice()'),
+  actionsCoreWarning: jest.fn().mockName('Mock: "@actions/core".warning()'),
+  actionsCoreError: jest.fn().mockName('Mock: "@actions/core".error()'),
   loggerStart: jest.fn().mockName('Mock: "src/logger".Logger.start()'),
   loggerStop: jest.fn().mockName('Mock: "src/logger".Logger.stop()'),
 };
@@ -19,6 +23,10 @@ jest.mock('aws-sdk', () => ({
 
 jest.mock('@actions/core', () => ({
   info: mocks.actionsCoreInfo,
+  debug: mocks.actionsCoreDebug,
+  notice: mocks.actionsCoreNotice,
+  warning: mocks.actionsCoreWarning,
+  error: mocks.actionsCoreError,
   setFailed: mocks.actionsCoreSetFailed,
   setOutput: mocks.actionsCoreSetOutput,
 }));

diff --git a/__tests__/src/logger/CloudWatchLogger.ts b/__tests__/src/logger/CloudWatchLogger.ts
@@ -3,6 +3,9 @@ import { AWSError } from 'aws-sdk';
 const mocks = {
   getLogEvents: jest.fn().mockName('Mock: "aws-sdk".CloudWatchLogs.prototype.getLogEvents()'),
   actionsCoreInfo: jest.fn().mockName('Mock: "@actions/core".info()'),
+  actionsCoreDebug: jest.fn().mockName('Mock: "@actions/core".debug()'),
+  actionsCoreNotice: jest.fn().mockName('Mock: "@actions/core".notice()'),
+  actionsCoreWarning: jest.fn().mockName('Mock: "@actions/core".warning()'),
   actionsCoreError: jest.fn().mockName('Mock: "@actions/core".error()'),
 }
 
@@ -14,6 +17,9 @@ jest.mock("aws-sdk", () => ({
 
 jest.mock("@actions/core", () => ({
   info: mocks.actionsCoreInfo,
+  debug: mocks.actionsCoreDebug,
+  notice: mocks.actionsCoreNotice,
+  warning: mocks.actionsCoreWarning,
   error: mocks.actionsCoreError,
 }));
 

diff --git a/__tests__/src/logger/Logger.ts b/__tests__/src/logger/Logger.ts
@@ -2,12 +2,18 @@ const mocks = {
   actionsCoreError: jest.fn().mockName('Mock: "@actions/core".error()'),
   actionsCoreStartGroup: jest.fn().mockName('Mock: "@actions/core".startGroup()'),
   actionsCoreEndGroup: jest.fn().mockName('Mock: "@actions/core".endGroup()'),
+  actionsCoreDebug: jest.fn().mockName('Mock: "@actions/core".debug()'),
+  actionsCoreNotice: jest.fn().mockName('Mock: "@actions/core".notice()'),
+  actionsCoreWarning: jest.fn().mockName('Mock: "@actions/core".warning()'),
 }
 
 jest.mock("@actions/core", () => ({
   error: mocks.actionsCoreError,
   startGroup: mocks.actionsCoreStartGroup,
   endGroup: mocks.actionsCoreEndGroup,
+  debug: mocks.actionsCoreDebug,
+  notice: mocks.actionsCoreNotice,
+  warning: mocks.actionsCoreWarning,
 }));
 
 import { Logger } from '../../../src/logger';

diff --git a/__tests__/src/utils/index.ts b/__tests__/src/utils/index.ts
@@ -0,0 +1,30 @@
+const utilsMocks = {
+  actionsCoreDebug: jest.fn().mockName('Mock: "@actions/core".debug()'),
+  actionsCoreError: jest.fn().mockName('Mock: "@actions/core".error()'),
+};
+
+jest.mock('@actions/core', () => ({
+  debug: utilsMocks.actionsCoreDebug,
+  error: utilsMocks.actionsCoreError,
+}));
+
+describe('Utils functionality testing', () => {
+  it('should report about error in stringifying of additional data for debug', async () => {
+    const error = new Error('Test error');
+    const stringifyMock = jest.spyOn(JSON, 'stringify').mockImplementation(() => { throw new Error('Test error'); });
+
+    const { debug } = jest.requireActual('../../../src/utils.ts');
+    const { actionsCoreDebug, actionsCoreError } = utilsMocks;
+
+    expect(() => debug('Test')).not.toThrow();
+    expect(stringifyMock).toBeCalledTimes(1);
+    expect(actionsCoreDebug).toBeCalledTimes(2);
+    expect(actionsCoreError).toBeCalledTimes(1);
+
+    expect(actionsCoreError).lastCalledWith(error);
+    expect(actionsCoreDebug).nthCalledWith(1, `[DEBUG] Can't stringify additional debug data for the message: Test. Error: Test error`);
+    expect(actionsCoreDebug).nthCalledWith(2, `[DEBUG] Test`);
+
+    stringifyMock.mockRestore();
+  });
+});
diff --git a/dist/index.js b/dist/index.js
diff --git a/src/codebuildjob.ts b/src/codebuildjob.ts
@@ -1,6 +1,7 @@
 import * as core from '@actions/core';
 import { CodeBuild } from 'aws-sdk';
 import { Logger } from './logger';
+import { debug } from './utils';
 import {
   BatchGetBuildsOutput,
   BuildPhaseType,
@@ -19,6 +20,8 @@ class CodeBuildJob {
   protected currentPhase: BuildPhaseType | 'STARTING' = 'STARTING';
 
   constructor(params: StartBuildInput) {
+    debug('[CodeBuildJob] Created new CodeBuildJob instance with parameters:', params);
+
     this.params = params;
 
     this.wait = this.wait.bind(this);
@@ -31,7 +34,9 @@ class CodeBuildJob {
     const { projectName } = this.params;
 
     core.info(`Starting "${projectName}" CodeBuild project job`);
+    debug('[CodeBuildJob] Doing request CodeBuild.startBuild() with parameters', this.params);
     const startBuildOutput = await this.client.startBuild(this.params).promise();
+    debug('[CodeBuildJob]Received response from CodeBuild.startBuild() request', startBuildOutput);
 
     if (!startBuildOutput || !startBuildOutput.build) {
       throw new Error(`Can't start ${projectName} CodeBuild job. Empty response from AWS API Endpoint`);
@@ -51,6 +56,7 @@ class CodeBuildJob {
         logStreamName: (cloudWatchLogs.streamName || (build.id as string).split(':').at(-1)) as string,
       }
 
+      debug('[CodeBuildJob] Creating CloudWatch Logger with parameters:', options);
       this.logger = new Logger(options);
     }
 
@@ -65,10 +71,15 @@ class CodeBuildJob {
    * Canceling job execution
    */
   public async cancelBuild() {
-    core.info(`Canceling job ${this.build.id}`);
-    await this.client.stopBuild({ id: this.build.id as string }).promise();
+    const request = { id: this.build.id as string };
+
+    core.warning(`Canceling job ${this.build.id}`);
+    debug(' [CodeBuildJob]Sending request to cancel job execution CodeBuild.stopBuild() with parameters:', request);
+    const response = await this.client.stopBuild(request).promise();
+    debug('[CodeBuildJob] Received response from CodeBuild.stopBuild() request:', response);
     core.info(`Build ${this.build.id} was successfully canceled`);
 
+    debug('[CodeBuildJob] Canceling next request to the CodeBuild.batchGetBuilds()');
     clearTimeout(this.timeout);
     this.logger?.stop(true);
   }
@@ -78,26 +89,39 @@ class CodeBuildJob {
    * @protected
    */
   protected async wait() {
+    debug('[CodeBuildJob] Starting updating job status');
+
     const { id } = this.build as CodeBuild.Build;
-    const { builds } = await this.client.batchGetBuilds({ ids: [ id as string ] }).promise() as BatchGetBuildsOutput;
+    const request = { ids: [ id as string ] };
+
+    debug('[CodeBuildJob] Doing request to the CodeBuild.batchGetBuilds() with parameters:', request);
+    const response = await this.client.batchGetBuilds(request).promise() as BatchGetBuildsOutput;
+    debug('[CodeBuildJob] Received response from CodeBuild.batchGetBuilds() call:', response);
+
+    const { builds } = response;
     const build = (builds as Builds).at(0) as Build;
     const { currentPhase, buildStatus } = build;
 
     const phasesWithoutLogs: BuildPhaseType[] = ['SUBMITTED', 'QUEUED', 'PROVISIONING'];
     if (!phasesWithoutLogs.includes(currentPhase as BuildPhaseType)) {
+      debug('[CodeBuildJob] Starting listening for job logs output');
       this.logger?.start();
     }
 
     if (currentPhase === 'COMPLETED') {
+      debug('[CodeBuildJob] Stopping listening of job logs output');
       this.logger?.stop();
 
       if (buildStatus !== 'IN_PROGRESS' && buildStatus !== 'SUCCEEDED') {
+        debug('[CodeBuildJob] Detected job execution finished');
         process.on('exit', () => {
           core.setFailed(`Job ${this.build.id} was finished with failed status: ${buildStatus}`);
         });
       }
 
       if (buildStatus !== 'IN_PROGRESS') {
+        debug('[CodeBuildJob] Composing GitHub Action outputs');
+
         core.setOutput('id', build.id);
         core.setOutput('success', buildStatus === 'SUCCEEDED');
         core.setOutput('buildNumber', build.buildNumber);
@@ -109,10 +133,11 @@ class CodeBuildJob {
 
     if (currentPhase !== this.currentPhase) {
       this.currentPhase = currentPhase as BuildPhaseType;
-      core.info(`Build phase was changed to the "${this.currentPhase}"`);
+      core.notice(`Build phase was changed to the "${this.currentPhase}"`);
     }
 
     if (build.buildStatus === 'IN_PROGRESS') {
+      debug('[CodeBuildJob] Scheduling next request to the CodeBuild.batchGetBuilds() API');
       this.timeout = setTimeout(this.wait, 5000);
     }
   }

diff --git a/src/logger.ts b/src/logger.ts
@@ -1,6 +1,7 @@
 import * as core from '@actions/core';
 import { CloudWatchLogs, AWSError } from 'aws-sdk';
 import { GetLogEventsRequest, Timestamp } from 'aws-sdk/clients/cloudwatchlogs';
+import { debug } from './utils';
 
 /**
  * CloudWatchLogs logs stream connector
@@ -53,6 +54,8 @@ class CloudWatchLogger {
    * @param { logGroupName: string, logStreamName: string } params
    */
   constructor(params: { logGroupName: string, logStreamName: string }) {
+    debug('[CloudWatchLogger] Created new CloudWatchLogger logger instance with parameters:', params);
+
     this.params = params;
     this.getEvents = this.getEvents.bind(this);
     this.startListen = this.startListen.bind(this);
@@ -66,6 +69,7 @@ class CloudWatchLogger {
     await this.getEvents();
 
     if (!this.isStopping) {
+      debug('[CloudWatchLogger] Scheduling next call to the CloudWatchLogs.getLogEvents() API');
       this.timeout = setTimeout(this.startListen, this.timeoutDelay);
     }
   }
@@ -78,6 +82,7 @@ class CloudWatchLogger {
     this.isStopping = true;
 
     if (force) {
+      debug('[CloudWatchLogger] Canceling next calls to the CloudWatchLogs.getLogEvents() API');
       clearTimeout(this.timeout);
     }
   }
@@ -88,6 +93,8 @@ class CloudWatchLogger {
    * @protected
    */
   protected async getEvents(req?: GetLogEventsRequest) {
+    debug('[CloudWatchLogger] Executing CloudWatchLogger.getEvents() method with parameters:', req || 'Without parameters');
+
     // composing request to the CloudWatch Logs API
     const request: GetLogEventsRequest = {
       ...(req || this.params),
@@ -107,8 +114,11 @@ class CloudWatchLogger {
 
     // executing request to the CloudWatch Logs API
     try {
-      const { events, nextForwardToken: nextToken } = await this.client.getLogEvents(request).promise();
+      debug('[CloudWatchLogger] Doing request to the CloudWatchLogs.getLogEvents() with parameters:', request);
+      const response = await this.client.getLogEvents(request).promise();
+      debug('[CloudWatchLogger] Received response from CloudWatchLogs.getLogEvents():', response);
 
+      const { events, nextForwardToken: nextToken } = response;
       if (events && events.length > 0) {
         // reporting about new messages into logs stream
         events.forEach(e => core.info((e.message as string).trimRight()));
@@ -128,6 +138,7 @@ class CloudWatchLogger {
 
       // in case if we do not have access to read logs, no make sense listen it again
       if (code === 'AccessDeniedException') {
+        debug('[CloudWatchLogger] Received error AccessDeniedException in response from CloudWatchLogs.getLogEvents():', message);
         this.stopListen(true);
       }
 
@@ -159,8 +170,11 @@ class Logger {
    * @param {string} params.logStreamName - CloudWatch Stream name in provided CloudWatch Logs group name
    */
   constructor(protected readonly params: { type: string, logGroupName: string, logStreamName: string }) {
+    debug('[Logger] Creating a new Logger wrapper instance with parameters:', params);
+
     const { type, logGroupName, logStreamName } = params;
     if (type === 'cloudwatch') {
+      debug('[Logger] Creating new CloudWatchLogger instance with parameters:', params);
       this.logger = new CloudWatchLogger({ logGroupName, logStreamName });
     } else {
       throw new Error(`No found CloudWatch config for listening`);
@@ -172,6 +186,7 @@ class Logger {
    */
   public start() {
     if (!this.isStarted) {
+      debug('[Logger] Starting listening a new messages from AWS CodeBuild job output');
       this.isStarted = true;
       this.logger.startListen().catch(e => core.error(e as Error));
 
@@ -190,6 +205,7 @@ class Logger {
    * @param {boolean=} force - Is that stop signal should be processed immediately
    */
   public stop(force?: boolean) {
+    debug('[Logger] Triggered stopping listening of logs');
     this.logger.stopListen(force);
   }
 }

diff --git a/src/utils.ts b/src/utils.ts
@@ -0,0 +1,27 @@
+import { debug as coreDebug, error as coreError } from '@actions/core';
+
+/**
+ * Wrapper to display debug messages
+ * @param {string} message - Debug message to display
+ * @param {?=} data - Additional data that should be displayed in the debug output
+ */
+function debug(message: string, data?: unknown) {
+  let additionalData;
+  try {
+    additionalData = JSON.stringify(data);
+  } catch (error) {
+    const { message: errorMessage } = error as Error;
+    coreDebug(`[DEBUG] Can't stringify additional debug data for the message: ${message}. Error: ${errorMessage}`);
+    coreError(error as Error);
+  }
+
+  if (additionalData) {
+    coreDebug(`[DEBUG] ${message}\n${additionalData}`);
+  } else {
+    coreDebug(`[DEBUG] ${message}`);
+  }
+}
+
+export {
+  debug,
+};