add session time components instrumentation

.gitignore

@@ -8,3 +8,4 @@ package-lock.json
 .env.*
 log/*.log
 results/*
+coverage

bin/commands/runs.js

@@ -9,14 +9,21 @@ const archiver = require("../helpers/archiver"),
   utils = require("../helpers/utils"),
   fileHelpers = require("../helpers/fileHelpers"),
   syncRunner = require("../helpers/syncRunner"),
-  reportGenerator = require('../helpers/reporterHTML').reportGenerator;
+  reportGenerator = require('../helpers/reporterHTML').reportGenerator,
+  {initTimeComponents, markBlockStart, markBlockEnd, getTimeComponents} = require('../helpers/timeComponents');
 
 module.exports = function run(args) {
   let bsConfigPath = utils.getConfigPath(args.cf);
   //Delete build_results.txt from log folder if already present.
+  initTimeComponents();
+  markBlockStart('deleteOldResults');
   utils.deleteResults();
+  markBlockEnd('deleteOldResults');
 
+  markBlockStart('validateBstackJson');
   return utils.validateBstackJson(bsConfigPath).then(function (bsConfig) {
+    markBlockEnd('validateBstackJson');
+    markBlockStart('setConfig');
     utils.setUsageReportingFlag(bsConfig, args.disableUsageReporting);
 
     utils.setDefaults(bsConfig, args);
@@ -56,10 +63,13 @@ module.exports = function run(args) {
 
     // set the no-wrap
     utils.setNoWrap(bsConfig, args);
+    markBlockEnd('setConfig');
 
     // Validate browserstack.json values and parallels specified via arguments
+    markBlockStart('validateConfig');
     return capabilityHelper.validate(bsConfig, args).then(function (cypressJson) {
-
+      markBlockEnd('validateConfig');
+      markBlockStart('preArchiveSteps');
       //get the number of spec files
       let specFiles = utils.getNumberOfSpecFiles(bsConfig, args, cypressJson);
 
@@ -69,17 +79,29 @@ module.exports = function run(args) {
       // warn if specFiles cross our limit
       utils.warnSpecLimit(bsConfig, args, specFiles);
 
+      markBlockEnd('preArchiveSteps');
       // Archive the spec files
+      markBlockStart('zip');
+      markBlockStart('zip.archive');
       return archiver.archive(bsConfig.run_settings, config.fileName, args.exclude).then(function (data) {
 
+        markBlockEnd('zip.archive');
         // Uploaded zip file
+        markBlockStart('zip.zipUpload');
         return zipUploader.zipUpload(bsConfig, config.fileName).then(async function (zip) {
+
+          markBlockEnd('zip.zipUpload');
+          markBlockEnd('zip');
           // Create build
 
           //setup Local Testing
+          markBlockStart('localSetup');
           let bs_local = await utils.setupLocalTesting(bsConfig, args);
-
+          markBlockEnd('localSetup');
+          markBlockStart('createBuild');
           return build.createBuild(bsConfig, zip).then(function (data) {
+            markBlockEnd('createBuild');
+            markBlockEnd('total');
             let message = `${data.message}! ${Constants.userMessages.BUILD_CREATED} with build id: ${data.build_id}`;
             let dashboardLink = `${Constants.userMessages.VISIT_DASHBOARD} ${data.dashboard_url}`;
             utils.exportResults(data.build_id, `${config.dashboardUrl}${data.build_id}`);
@@ -114,7 +136,19 @@ module.exports = function run(args) {
             logger.info(message);
             logger.info(dashboardLink);
             if(!args.sync) logger.info(Constants.userMessages.EXIT_SYNC_CLI_MESSAGE.replace("<build-id>",data.build_id));
-            utils.sendUsageReport(bsConfig, args, `${message}\n${dashboardLink}`, Constants.messageTypes.SUCCESS, null);
+            let dataToSend = {
+              time_components: getTimeComponents(),
+              build_id: data.build_id,
+            };
+            if (bsConfig && bsConfig.connection_settings) {
+              if (bsConfig.connection_settings.local_mode) {
+                dataToSend.local_mode = bsConfig.connection_settings.local_mode;
+              }
+              if (bsConfig.connection_settings.usedAutoLocal) {
+                dataToSend.used_auto_local = bsConfig.connection_settings.usedAutoLocal;
+              }
+            }
+            utils.sendUsageReport(bsConfig, args, `${message}\n${dashboardLink}`, Constants.messageTypes.SUCCESS, null, dataToSend);
             return;
           }).catch(async function (err) {
             // Build creation failed

bin/helpers/sync/syncSpecsLogs.js

@@ -103,6 +103,9 @@ let printSpecsStatus = (bsConfig, buildDetails) => {
         whileProcess(callback)
       },
       function(err, result) { // when loop ends
+        if (err) {
+          utils.sendUsageReport(bsConfig, {}, `buildId: ${buildDetails.build_id}`, 'error', 'sync_cli_error', err);
+        }
         logger.info(lineSeparator);
         specSummary.duration =  endTime - startTime
         resolve(specSummary)

bin/helpers/timeComponents.js

@@ -0,0 +1,65 @@
+'use strict'
+
+const { isUndefined } = require('./utils');
+
+let sessionTimes = {
+  referenceTimes: {
+    absoluteStartTime: Date.now()
+  }, // Absolute times which needs to be used later to calculate logTimes
+  logTimes: {}, // Time Difference in ms which we need to push to EDS
+};
+
+const initTimeComponents = () => {
+  sessionTimes = {referenceTimes: {absoluteStartTime: Date.now()}, logTimes: {}};
+};
+
+const markBlockStart = (blockName) => {
+  sessionTimes.referenceTimes[blockName] = Date.now();
+};
+
+const markBlockEnd = (blockName) => {
+  const startTime = sessionTimes.referenceTimes[blockName] || sessionTimes.referenceTimes.absoluteStartTime;
+  markBlockDiff(blockName, startTime, Date.now());
+};
+
+const markBlockDiff = (blockName, startTime, stopTime) => {
+  sessionTimes.logTimes[blockName] = stopTime - startTime;
+}
+
+const getTimeComponents = () => {
+  const data = convertDotToNestedObject(sessionTimes.logTimes);
+
+  return data;
+};
+
+const convertDotToNestedObject = (dotNotationObject) => {
+  let nestedObject = {};
+
+  Object.keys(dotNotationObject).forEach((key) => {
+    let dotKeys = key.split('.');
+    let currentKey = nestedObject;
+    for(let i = 0; i < dotKeys.length - 1; i++) {
+      if (isUndefined(currentKey[dotKeys[i]])) {
+        currentKey[dotKeys[i]] = {};
+      } else if (Number.isInteger(currentKey[dotKeys[i]])) {
+        currentKey[dotKeys[i]] = {total: currentKey[dotKeys[i]]};
+      }
+      currentKey = currentKey[dotKeys[i]];
+    }
+    if (isUndefined(currentKey[dotKeys[dotKeys.length - 1]]) || Number.isInteger(currentKey[dotKeys[dotKeys.length - 1]])) {
+      currentKey[dotKeys[dotKeys.length - 1]] = dotNotationObject[key];
+    } else {
+      currentKey[dotKeys[dotKeys.length - 1]].total = dotNotationObject[key];
+    }
+  });
+
+  return nestedObject;
+};
+
+module.exports = {
+  initTimeComponents,
+  markBlockStart,
+  markBlockEnd,
+  markBlockDiff,
+  getTimeComponents,
+};

bin/helpers/usageReporting.js

@@ -6,7 +6,8 @@ const cp = require("child_process"),
   path = require('path');
 
 const config = require('./config'),
-  fileLogger = require('./logger').fileLogger;
+  fileLogger = require('./logger').fileLogger,
+  utils = require('./utils');
 
 function get_version(package_name) {
   try {
@@ -33,7 +34,7 @@ function local_cypress_version(bsConfig) {
   // 1. check version of Cypress installed in local project
   // 2. check version of Cypress installed globally if not present in project
 
-  if (bsConfig && bsConfig.run_settings.cypressProjectDir) {
+  if (bsConfig && bsConfig.run_settings && bsConfig.run_settings.cypressProjectDir) {
     let version = get_version(path.join(bsConfig.run_settings.cypressProjectDir, 'node_modules', '.bin', 'cypress'));
     if (!version) {
       version = get_version('cypress');
@@ -80,7 +81,7 @@ function cli_version_and_path(bsConfig) {
   // 1. check version of Cypress installed in local project
   // 2. check version of Cypress installed globally if not present in project
 
-  if (bsConfig && bsConfig.run_settings.cypressProjectDir) {
+  if (bsConfig && bsConfig.run_settings && bsConfig.run_settings.cypressProjectDir) {
     let _path = path.join(bsConfig.run_settings.cypressProjectDir, 'node_modules', 'browserstack-cypress');
     let version = get_version(_path);
     if (!version) {
@@ -174,7 +175,7 @@ function send(args) {
 
   let bsConfig = args.bstack_config;
   let cli_details = cli_version_and_path(bsConfig);
-  let data = {}
+  let data = utils.isUndefined(args.data) ? {} : args.data;
 
   if (bsConfig && bsConfig.run_settings) {
     data.cypress_version = bsConfig.run_settings.cypress_version

bin/helpers/utils.js

@@ -107,14 +107,16 @@ exports.sendUsageReport = (
   args,
   message,
   message_type,
-  error_code
+  error_code,
+  data
 ) => {
   usageReporting.send({
     cli_args: args,
     message: message,
     message_type: message_type,
     error_code: error_code,
     bstack_config: bsConfig,
+    data,
   });
 };
 
@@ -448,6 +450,7 @@ exports.setupLocalTesting = (bsConfig, args) => {
         bsConfig, bsConfig['connection_settings']['local_identifier']
       );
       if (!localIdentifierRunning){
+        bsConfig.connection_settings.usedAutoLocal = true;
         var bs_local = this.getLocalBinary();
         var bs_local_args = this.setLocalArgs(bsConfig, args);
         let that = this;

test/unit/bin/commands/runs.js

@@ -5,6 +5,7 @@ const chai = require("chai"),
 const Constants = require("../../../../bin/helpers/constants"),
   logger = require("../../../../bin/helpers/logger").winstonLogger,
   testObjects = require("../../support/fixtures/testObjects");
+const { initTimeComponents, markBlockStart, markBlockEnd } = require("../../../../bin/helpers/timeComponents");
 const { setHeaded, setupLocalTesting, stopLocalBinary, setUserSpecs, setLocalConfigFile } = require("../../../../bin/helpers/utils");
 
 const proxyquire = require("proxyquire").noCallThru();
@@ -618,6 +619,10 @@ describe("runs", () => {
       setNoWrapStub = sandbox.stub();
       getNumberOfSpecFilesStub = sandbox.stub().returns([]);
       setLocalConfigFileStub = sandbox.stub();
+      getTimeComponentsStub = sandbox.stub().returns({});
+      initTimeComponentsStub = sandbox.stub();
+      markBlockStartStub = sandbox.stub();
+      markBlockEndStub = sandbox.stub();
     });
 
     afterEach(() => {
@@ -630,6 +635,7 @@ describe("runs", () => {
       let errorCode = null;
       let message = `Success! ${Constants.userMessages.BUILD_CREATED} with build id: random_build_id`;
       let dashboardLink = `${Constants.userMessages.VISIT_DASHBOARD} ${dashboardUrl}`;
+      let data = {time_components: {}, build_id: 'random_build_id'}
 
       const runs = proxyquire('../../../../bin/commands/runs', {
         '../helpers/utils': {
@@ -656,7 +662,7 @@ describe("runs", () => {
           setDefaults: setDefaultsStub,
           isUndefined: isUndefinedStub,
           getNumberOfSpecFiles: getNumberOfSpecFilesStub,
-          setLocalConfigFile: setLocalConfigFileStub
+          setLocalConfigFile: setLocalConfigFileStub,
         },
         '../helpers/capabilityHelper': {
           validate: capabilityValidatorStub,
@@ -676,6 +682,12 @@ describe("runs", () => {
         '../helpers/config': {
           dashboardUrl: dashboardUrl,
         },
+        '../helpers/timeComponents': {
+          initTimeComponents: initTimeComponentsStub,
+          getTimeComponents: getTimeComponentsStub,
+          markBlockStart: markBlockStartStub,
+          markBlockEnd: markBlockEndStub,
+        }
       });
 
       validateBstackJsonStub.returns(Promise.resolve(bsConfig));
@@ -713,13 +725,16 @@ describe("runs", () => {
           sinon.assert.calledOnce(exportResultsStub);
           sinon.assert.calledOnce(deleteResultsStub);
           sinon.assert.calledOnce(setDefaultsStub);
-          sinon.assert.calledOnceWithExactly(
-            sendUsageReportStub,
-            bsConfig,
-            args,
-            `${message}\n${dashboardLink}`,
-            messageType,
-            errorCode
+          sinon.assert.match(
+            sendUsageReportStub.getCall(0).args,
+            [
+              bsConfig,
+              args,
+              `${message}\n${dashboardLink}`,
+              messageType,
+              errorCode,
+              data
+            ]
           );
         });
     });

test/unit/bin/helpers/sync/syncSpecsLogs.js

@@ -14,16 +14,19 @@ var syncSpecsLogs = rewire("../../../../../bin/helpers/sync/syncSpecsLogs.js");
 var logger = require("../../../../../bin/helpers/logger").syncCliLogger;
 var Constants = require("../../../../../bin/helpers/constants.js");
 var config = require("../../../../../bin/helpers/config.js");
+var utils = require("../../../../../bin/helpers/utils");
 
 describe("syncSpecsLogs", () => {
   var sandbox;
 
   beforeEach(() => {
     sandbox = sinon.createSandbox();
+    sinon.stub(utils, 'sendUsageReport');
   });
 
   afterEach(() => {
     sandbox.restore();
+    utils.sendUsageReport.restore();
   });
 
   context("getCombinationName", () => {