add: debug logs for timeout

Author: 07souravkunda

bin/testObservability/helper/helper.js

@@ -9,6 +9,8 @@ const { promisify } = require('util');
 const gitconfig = require('gitconfiglocal');
 const { spawn, execSync } = require('child_process');
 const glob = require('glob');
+const util = require('util');
+
 const { runOptions } = require('../../helpers/runnerArgs')
 
 const pGitconfig = promisify(gitconfig);
@@ -38,6 +40,13 @@ exports.pending_test_uploads = {
   count: 0
 };
 
+exports.debugOnConsole = (text) => {
+  if ((process.env.BROWSERSTACK_OBSERVABILITY_DEBUG + '')  === "true" || 
+      (process.env.BROWSERSTACK_OBSERVABILITY_DEBUG + '') === "1") {
+    consoleHolder.log(`[ OBSERVABILITY ] ${text}`);
+  }
+}
+
 exports.debug = (text, shouldReport = false, throwable = null) => {
   if (process.env.BROWSERSTACK_OBSERVABILITY_DEBUG === "true" || process.env.BROWSERSTACK_OBSERVABILITY_DEBUG === "1") {
     logger.info(`[ OBSERVABILITY ] ${text}`);
@@ -475,14 +484,18 @@ exports.batchAndPostEvents = async (eventUrl, kind, data) => {
   };
 
   try {
+    const eventsUuids = data.map(eventData => `${eventData.event_type}:${eventData.test_run ? eventData.test_run.uuid : (eventData.hook_run ? eventData.hook_run.uuid : null)}`).join(', ');
+    exports.debugOnConsole(`[Request Batch Send] for events:uuids ${eventsUuids}`);
     const response = await nodeRequest('POST',eventUrl,data,config);
+    exports.debugOnConsole(`[Request Batch Response] for events:uuids ${eventsUuids}`);
     if(response.data.error) {
       throw({message: response.data.error});
     } else {
       exports.debug(`${kind} event successfull!`)
       exports.pending_test_uploads.count = Math.max(0,exports.pending_test_uploads.count - data.length);
     }
   } catch(error) {
+    exports.debugOnConsole(`[Request Error] Error in sending request ${util.format(error)}`);
     if (error.response) {
       exports.debug(`EXCEPTION IN ${kind} REQUEST TO TEST OBSERVABILITY : ${error.response.status} ${error.response.statusText} ${JSON.stringify(error.response.data)}`, true, error);
     } else {
@@ -522,6 +535,7 @@ exports.uploadEventData = async (eventData, run=0) => {
 
       exports.requestQueueHandler.start();
       const { shouldProceed, proceedWithData, proceedWithUrl } = exports.requestQueueHandler.add(eventData);
+      exports.debugOnConsole(`[Request Queue] ${eventData.event_type} with uuid ${eventData.test_run ? eventData.test_run.uuid : (eventData.hook_run ? eventData.hook_run.uuid : null)} is added`)
       if(!shouldProceed) {
         return;
       } else if(proceedWithData) {
@@ -538,7 +552,10 @@ exports.uploadEventData = async (eventData, run=0) => {
       };
 
       try {
+        const eventsUuids = data.map(eventData => `${eventData.event_type}:${eventData.test_run ? eventData.test_run.uuid : (eventData.hook_run ? eventData.hook_run.uuid : null)}`).join(', ');
+        exports.debugOnConsole(`[Request Send] for events:uuids ${eventsUuids}`);
         const response = await nodeRequest('POST',event_api_url,data,config);
+        exports.debugOnConsole(`[Request Repsonse] ${util.format(response.data)} for events:uuids ${eventsUuids}`)
         if(response.data.error) {
           throw({message: response.data.error});
         } else {
@@ -550,6 +567,7 @@ exports.uploadEventData = async (eventData, run=0) => {
           };
         }
       } catch(error) {
+        exports.debugOnConsole(`[Request Error] Error in sending request ${util.format(error)}`);
         if (error.response) {
           exports.debug(`EXCEPTION IN ${event_api_url !== exports.requestQueueHandler.eventUrl ? log_tag : 'Batch-Queue'} REQUEST TO TEST OBSERVABILITY : ${error.response.status} ${error.response.statusText} ${JSON.stringify(error.response.data)}`, true, error);
         } else {

bin/testObservability/reporter/index.js

@@ -57,7 +57,8 @@ const {
   getOSDetailsFromSystem,
   findGitConfig,
   getFileSeparatorData,
-  setCrashReportingConfigFromReporter
+  setCrashReportingConfigFromReporter,
+  debugOnConsole
 } = require('../helper/helper');
 
 const { consoleHolder } = require('../helper/constants');
@@ -123,7 +124,9 @@ class MyReporter {
       })
 
       .on(EVENT_TEST_PASS, async (test) => {
+        debugOnConsole(`[MOCHA EVENT] EVENT_TEST_PASS`);
         if(this.testObservability == true) {
+          debugOnConsole(`[MOCHA EVENT] EVENT_TEST_PASS for uuid: ${test.testAnalyticsId}`);
           if(!this.runStatusMarkedHash[test.testAnalyticsId]) {
             if(test.testAnalyticsId) this.runStatusMarkedHash[test.testAnalyticsId] = true;
             await this.sendTestRunEvent(test);
@@ -132,7 +135,9 @@ class MyReporter {
       })
 
       .on(EVENT_TEST_FAIL, async (test, err) => {
+        debugOnConsole(`[MOCHA EVENT] EVENT_TEST_FAIL`);
         if(this.testObservability == true) {
+          debugOnConsole(`[MOCHA EVENT] EVENT_TEST_FAIL for uuid: ${test.testAnalyticsId}`);
           if((test.testAnalyticsId && !this.runStatusMarkedHash[test.testAnalyticsId]) || (test.hookAnalyticsId && !this.runStatusMarkedHash[test.hookAnalyticsId])) {
             if(test.testAnalyticsId) {
               this.runStatusMarkedHash[test.testAnalyticsId] = true;
@@ -146,8 +151,10 @@ class MyReporter {
       })
 
       .on(EVENT_TEST_PENDING, async (test) => {
+        debugOnConsole(`[MOCHA EVENT] EVENT_TEST_PENDING`);
         if(this.testObservability == true) {
           if(!test.testAnalyticsId) test.testAnalyticsId = uuidv4();
+          debugOnConsole(`[MOCHA EVENT] EVENT_TEST_PENDING for uuid: ${test.testAnalyticsId}`);
           if(!this.runStatusMarkedHash[test.testAnalyticsId]) {
             this.runStatusMarkedHash[test.testAnalyticsId] = true;
             await this.sendTestRunEvent(test,undefined,false,"TestRunSkipped");
@@ -156,13 +163,17 @@ class MyReporter {
       })
 
       .on(EVENT_TEST_BEGIN, async (test) => {
+        debugOnConsole(`[MOCHA EVENT] EVENT_TEST_BEGIN`);
+        debugOnConsole(`[MOCHA EVENT] EVENT_TEST_BEGIN for uuid: ${test.testAnalyticsId}`);
         if (this.runStatusMarkedHash[test.testAnalyticsId]) return;
         if(this.testObservability == true) {
           await this.testStarted(test);
         }
       })
 
       .on(EVENT_TEST_END, async (test) => {
+        debugOnConsole(`[MOCHA EVENT] EVENT_TEST_END`);
+        debugOnConsole(`[MOCHA EVENT] EVENT_TEST_BEGIN for uuid: ${test.testAnalyticsId}`);
         if (this.runStatusMarkedHash[test.testAnalyticsId]) return;
         if(this.testObservability == true) {
           if(!this.runStatusMarkedHash[test.testAnalyticsId]) {
@@ -318,6 +329,8 @@ class MyReporter {
         }
       };
 
+      debugOnConsole(`${eventType} for uuid: ${testData.uuid}`);
+
       if(eventType.match(/TestRunFinished/) || eventType.match(/TestRunSkipped/)) {
         testData['meta'].steps = JSON.parse(JSON.stringify(this.currentTestCucumberSteps));
         this.currentTestCucumberSteps = [];