Add logger

package.json

@@ -64,6 +64,7 @@
     "node": ">=8.0.0"
   },
   "dependencies": {
+    "@types/yargs-parser": "^13.1.0",
     "axios": "^0.19.0",
     "del": "^5.1.0",
     "find-up": "^4.1.0",
@@ -75,11 +76,11 @@
     "make-dir": "^3.0.0",
     "ora": "^3.4.0",
     "strip-json-comments": "^3.0.1",
+    "winston": "^3.2.1",
     "yargs": "^14.0.0"
   },
   "devDependencies": {
     "@types/core-js": "^2.5.2",
-    "@types/find-up": "^4.0.0",
     "@types/inquirer": "^6.5.0",
     "@types/jest": "^24.0.18",
     "@types/lodash": "^4.14.138",
@@ -88,12 +89,11 @@
     "@types/lodash.isempty": "^4.4.6",
     "@types/lodash.isstring": "^4.0.6",
     "@types/node": "^10.14.16",
-    "@types/strip-json-comments": "^3.0.0",
     "@types/yargs": "^13.0.2",
-    "@typescript-eslint/eslint-plugin": "^2.1.0",
-    "@typescript-eslint/parser": "^2.1.0",
+    "@typescript-eslint/eslint-plugin": "^2.2.0",
+    "@typescript-eslint/parser": "^2.2.0",
     "eslint": "^6.3.0",
-    "eslint-config-prettier": "^6.2.0",
+    "eslint-config-prettier": "^6.3.0",
     "eslint-plugin-import": "^2.18.2",
     "eslint-plugin-prettier": "^3.1.0",
     "husky": "^3.0.5",
@@ -103,6 +103,6 @@
     "prettier": "^1.18.2",
     "ts-jest": "^24.0.2",
     "ts-node": "^8.3.0",
-    "typescript": "^3.6.2"
+    "typescript": "^3.6.3"
   }
 }

src/steps/__snapshots__/steps.test.ts.snap → src/__snapshots__/runWithOptions.test.ts.snap

@@ -1,6 +1,6 @@
 // Jest Snapshot v1, https://goo.gl/fbAQLP
 
-exports[`run through steps exec should be called with correct args 1`] = `
+exports[`runWithOptions exec should be called with correct args 1`] = `
 Array [
   Array [
     "git remote rm origin",
@@ -59,7 +59,7 @@ Array [
 ]
 `;
 
-exports[`run through steps git clone should be called with correct args 1`] = `
+exports[`runWithOptions git clone should be called with correct args 1`] = `
 Array [
   Array [
     "git clone https://myAccessToken@github.com/elastic/kibana.git --progress",
@@ -72,7 +72,7 @@ Array [
 ]
 `;
 
-exports[`run through steps prompt calls should match snapshot 1`] = `
+exports[`runWithOptions prompt calls should match snapshot 1`] = `
 Array [
   Array [
     Array [

src/index.ts

@@ -1,22 +1,6 @@
 #!/usr/bin/env node
 
-import { getOptions } from './options/options';
-import { initSteps } from './steps/steps';
+import { runWithArgs } from './runWithArgs';
+const args = process.argv.slice(2);
 
-async function init() {
-  try {
-    const args = process.argv.slice(2);
-    const options = await getOptions(args);
-    return await initSteps(options);
-  } catch (e) {
-    if (e.name === 'HandledError') {
-      console.error(e.message);
-    } else {
-      console.error(e);
-    }
-
-    process.exit(1);
-  }
-}
-
-init();
+runWithArgs(args);

src/options/cliArgs.test.ts

@@ -49,7 +49,8 @@ describe('getOptionsFromCliArgs', () => {
       resetAuthor: false,
       sha: undefined,
       upstream: 'sqren/backport-demo',
-      username: 'sqren'
+      username: 'sqren',
+      verbose: false
     });
   });
 

src/options/cliArgs.ts

@@ -122,6 +122,11 @@ export function getOptionsFromCliArgs(
       description: 'Github username',
       type: 'string'
     })
+    .option('verbose', {
+      default: false,
+      description: 'Show additional debug information',
+      type: 'boolean'
+    })
     .alias('v', 'version')
     .version()
     .help().argv;

src/options/options.test.ts

@@ -23,7 +23,8 @@ const validOptions: OptionsFromCliArgs = {
   resetAuthor: false,
   sha: undefined,
   upstream: 'elastic/kibana',
-  username: 'sqren'
+  username: 'sqren',
+  verbose: false
 };
 
 describe('validateRequiredOptions', () => {

src/runWithArgs.ts

@@ -0,0 +1,24 @@
+import { getOptions } from './options/options';
+import { runWithOptions } from './runWithOptions';
+import { HandledError } from './services/HandledError';
+import { initLogger } from './services/logger';
+
+export async function runWithArgs(args: string[]) {
+  const logger = initLogger();
+
+  try {
+    const options = await getOptions(args);
+    return await runWithOptions(options);
+  } catch (e) {
+    if (e instanceof HandledError) {
+      console.error(e.message);
+    } else {
+      console.error(e);
+    }
+
+    // wait exiting until logs have been flushed to disc
+    logger.on('finish', () => {
+      process.exit(1);
+    });
+  }
+}

src/steps/steps.test.ts → src/runWithOptions.test.ts

@@ -1,14 +1,14 @@
 import axios from 'axios';
 import inquirer from 'inquirer';
-import * as createPullRequest from '../services/github/createPullRequest';
-import * as fetchCommitsByAuthor from '../services/github/fetchCommitsByAuthor';
-import * as fs from '../services/fs-promisified';
-import { BackportOptions } from '../options/options';
-import { commitsWithPullRequestsMock } from '../services/github/mocks/commitsByAuthorMock';
-import { initSteps } from './steps';
-import * as childProcess from '../services/child-process-promisified';
-
-describe('run through steps', () => {
+import * as createPullRequest from './services/github/createPullRequest';
+import * as fetchCommitsByAuthor from './services/github/fetchCommitsByAuthor';
+import * as fs from './services/fs-promisified';
+import { BackportOptions } from './options/options';
+import { commitsWithPullRequestsMock } from './services/github/mocks/commitsByAuthorMock';
+import { runWithOptions } from './runWithOptions';
+import * as childProcess from './services/child-process-promisified';
+
+describe('runWithOptions', () => {
   let rpcExecMock: jest.SpyInstance;
   let rpcExecOriginalMock: jest.SpyInstance;
   let inquirerPromptMock: jest.SpyInstance;
@@ -48,7 +48,8 @@ describe('run through steps', () => {
       repoOwner: 'elastic',
       resetAuthor: false,
       sha: undefined,
-      username: 'sqren'
+      username: 'sqren',
+      verbose: false
     };
 
     rpcExecMock = (childProcess.exec as any) as jest.SpyInstance;
@@ -101,7 +102,7 @@ describe('run through steps', () => {
         }
       } as any);
 
-    await initSteps(options);
+    await runWithOptions(options);
   });
 
   it('should check whether access token is valid', () => {

src/runWithOptions.ts

@@ -0,0 +1,19 @@
+import { BackportOptions } from './options/options';
+import { verifyAccessToken } from './services/github/verifyAccessToken';
+import { doBackportVersions } from './ui/doBackportVersions';
+import { getBranches } from './ui/getBranches';
+import { getCommits } from './ui/getCommits';
+import { maybeSetupRepo } from './ui/maybeSetupRepo';
+import { logger } from './services/logger';
+
+export async function runWithOptions(options: BackportOptions) {
+  await verifyAccessToken(options);
+
+  const commits = await getCommits(options);
+  const branches = await getBranches(options);
+
+  await maybeSetupRepo(options);
+
+  logger.info(`Backporting ${JSON.stringify(commits)} ${branches.join(',')}`);
+  await doBackportVersions(options, commits, branches);
+}

src/services/env.ts

@@ -2,6 +2,10 @@ import { homedir } from 'os';
 import path from 'path';
 import { BackportOptions } from '../options/options';
 
+export function getLogfilePath() {
+  return path.join(homedir(), '.backport', 'backport.log');
+}
+
 export function getGlobalConfigPath() {
   return path.join(homedir(), '.backport', 'config.json');
 }

src/services/github/gqlRequest.ts

@@ -1,6 +1,7 @@
 import axios from 'axios';
 import get from 'lodash.get';
 import { HandledError } from '../HandledError';
+import { logger } from '../logger';
 
 interface GithubResponse<DataResponse> {
   data: DataResponse;
@@ -29,6 +30,8 @@ export async function gqlRequest<DataResponse>({
   accessToken: string;
 }) {
   try {
+    logger.verbose(query);
+    logger.verbose(variables as any);
     const { data } = await axios.post<GithubResponse<DataResponse>>(
       `https://${apiHostname}/graphql`,
       { query, variables },
@@ -40,14 +43,17 @@ export async function gqlRequest<DataResponse>({
       }
     );
 
+    logger.verbose(data);
+
     if (data.errors) {
-      throw new HandledError(
-        data.errors.map(error => error.message).join(', ')
-      );
+      const message = data.errors.map(error => error.message).join(', ');
+      throw new HandledError(message);
     }
 
     return data.data;
   } catch (e) {
+    logger.info(e.message);
+    logger.info(e.response);
     const responseError = get(e, 'response.data.errors') as {
       message: string;
     }[];

src/services/logger.ts

@@ -1,7 +1,48 @@
-export function log(...args: unknown[]) {
+import winston, { format } from 'winston';
+import yargs from 'yargs';
+import isString from 'lodash.isstring';
+import { getLogfilePath } from './env';
+
+const { combine, timestamp, printf } = format;
+const { argv } = yargs.help(false);
+
+// wrapper around console.log
+export function consoleLog(...args: unknown[]) {
   console.log(...args);
 }
 
-export function error(...args: unknown[]) {
-  console.error(...args);
+export let logger = ({
+  info: () => {},
+  verbose: () => {}
+} as unknown) as winston.Logger;
+
+export function initLogger() {
+  logger = winston.createLogger({
+    transports: [
+      // log to file
+      new winston.transports.File({
+        level: argv.verbose ? 'verbose' : 'info',
+        format: combine(
+          timestamp(),
+          printf(
+            ({ level, message, timestamp }) =>
+              `${timestamp} ${level}: ${formatMessage(message)}`
+          )
+        ),
+        filename: getLogfilePath()
+      })
+    ]
+  });
+  return logger;
+}
+
+function formatMessage(message: string | Record<any, any>) {
+  return isString(message) ? message : JSON.stringify(message, null, 2);
 }
+
+// log levels:
+// - error
+// - warn
+// - info
+// - verbose
+// - debug

src/test/integration/integration.test.ts

@@ -1,6 +1,6 @@
 import { once } from 'lodash';
 import { getOptions } from '../../options/options';
-import { initSteps } from '../../steps/steps';
+import { runWithOptions } from '../../runWithOptions';
 import { REMOTE_ORIGIN_REPO_PATH, REMOTE_FORK_REPO_PATH } from './envConstants';
 import { createSpies } from './createSpies';
 import {
@@ -24,7 +24,7 @@ describe('when a single commit is backported', () => {
       await deleteAndSetupEnvironment();
 
       const options = await getOptions([]);
-      await initSteps(options);
+      await runWithOptions(options);
     })
   );
 
@@ -88,7 +88,7 @@ describe('when a multiple commits are backported', () => {
       await deleteAndSetupEnvironment();
 
       const options = await getOptions([]);
-      await initSteps(options);
+      await runWithOptions(options);
     })
   );
 
@@ -160,7 +160,7 @@ describe('when disabling fork mode', () => {
       await deleteAndSetupEnvironment();
 
       const options = await getOptions(['--fork=false']);
-      await initSteps(options);
+      await runWithOptions(options);
     })
   );
 

src/steps/doBackportVersions.test.ts → src/ui/doBackportVersions.test.ts

@@ -142,7 +142,7 @@ myPrSuffix`
 
   describe('when cherry-picking fails', () => {
     function didResolveConflict(didResolve: boolean) {
-      const logSpy = jest.spyOn(logger, 'log');
+      const logSpy = jest.spyOn(logger, 'consoleLog');
 
       const execSpy = ((exec as any) as jest.SpyInstance).mockImplementation(
         async (cmd: string) => {