From eedd758c49387a5c2ae621ef62f8e4cca9a1ffe0 Mon Sep 17 00:00:00 2001 From: 07souravkunda Date: Wed, 28 Aug 2024 17:55:20 +0530 Subject: [PATCH 1/2] add: debug logs for timeout --- bin/testObservability/helper/helper.js | 18 ++++++++++++++++++ bin/testObservability/reporter/index.js | 15 ++++++++++++++- 2 files changed, 32 insertions(+), 1 deletion(-) diff --git a/bin/testObservability/helper/helper.js b/bin/testObservability/helper/helper.js index 6db43d87..e0f8d92c 100644 --- a/bin/testObservability/helper/helper.js +++ b/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,7 +484,10 @@ 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 { @@ -483,6 +495,7 @@ exports.batchAndPostEvents = async (eventUrl, kind, data) => { 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 { diff --git a/bin/testObservability/reporter/index.js b/bin/testObservability/reporter/index.js index 59ddc7b5..4a5628f3 100644 --- a/bin/testObservability/reporter/index.js +++ b/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,6 +163,8 @@ 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); @@ -163,6 +172,8 @@ class MyReporter { }) .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 = []; From a0b224b9ec547008f439de499a9b048c5e4e5b4b Mon Sep 17 00:00:00 2001 From: 07souravkunda Date: Fri, 30 Aug 2024 12:35:22 +0530 Subject: [PATCH 2/2] chore: comments --- bin/testObservability/helper/helper.js | 1 + bin/testObservability/reporter/index.js | 10 ++++++++++ 2 files changed, 11 insertions(+) diff --git a/bin/testObservability/helper/helper.js b/bin/testObservability/helper/helper.js index e0f8d92c..1b7da41f 100644 --- a/bin/testObservability/helper/helper.js +++ b/bin/testObservability/helper/helper.js @@ -509,6 +509,7 @@ const RequestQueueHandler = require('./requestQueueHandler'); exports.requestQueueHandler = new RequestQueueHandler(); exports.uploadEventData = async (eventData, run=0) => { + exports.debugOnConsole(`[uploadEventData] ${eventData.event_type}`); const log_tag = { ['TestRunStarted']: 'Test_Start_Upload', ['TestRunFinished']: 'Test_End_Upload', diff --git a/bin/testObservability/reporter/index.js b/bin/testObservability/reporter/index.js index 4a5628f3..d8c4cb9c 100644 --- a/bin/testObservability/reporter/index.js +++ b/bin/testObservability/reporter/index.js @@ -88,6 +88,7 @@ class MyReporter { }) .on(EVENT_HOOK_BEGIN, async (hook) => { + debugOnConsole(`[MOCHA EVENT] EVENT_HOOK_BEGIN`); if(this.testObservability == true) { if(!hook.hookAnalyticsId) { hook.hookAnalyticsId = uuidv4(); @@ -95,6 +96,7 @@ class MyReporter { delete this.runStatusMarkedHash[hook.hookAnalyticsId]; hook.hookAnalyticsId = uuidv4(); } + debugOnConsole(`[MOCHA EVENT] EVENT_HOOK_BEGIN for uuid: ${hook.hookAnalyticsId}`); hook.hook_started_at = (new Date()).toISOString(); hook.started_at = (new Date()).toISOString(); this.current_hook = hook; @@ -103,6 +105,7 @@ class MyReporter { }) .on(EVENT_HOOK_END, async (hook) => { + debugOnConsole(`[MOCHA EVENT] EVENT_HOOK_END`); if(this.testObservability == true) { if(!this.runStatusMarkedHash[hook.hookAnalyticsId]) { if(!hook.hookAnalyticsId) { @@ -115,6 +118,9 @@ class MyReporter { // Remove hooks added at hook start delete this.hooksStarted[hook.hookAnalyticsId]; + + debugOnConsole(`[MOCHA EVENT] EVENT_HOOK_END for uuid: ${hook.hookAnalyticsId}`); + await this.sendTestRunEvent(hook,undefined,false,"HookRunFinished"); } } @@ -185,10 +191,12 @@ class MyReporter { .once(EVENT_RUN_END, async () => { try { + debugOnConsole(`[MOCHA EVENT] EVENT_RUN_END`); if(this.testObservability == true) { const hookSkippedTests = getHookSkippedTests(this.runner.suite); for(const test of hookSkippedTests) { if(!test.testAnalyticsId) test.testAnalyticsId = uuidv4(); + debugOnConsole(`[MOCHA EVENT] EVENT_RUN_END TestRunSkipped for uuid: ${test.testAnalyticsId}`); await this.sendTestRunEvent(test,undefined,false,"TestRunSkipped"); } } @@ -390,6 +398,7 @@ class MyReporter { mapTestHooks(test); } } catch(e) { + debugOnConsole(`Exception in processing hook data for event ${eventType} with error : ${e}`); debug(`Exception in processing hook data for event ${eventType} with error : ${e}`, true, e); } @@ -486,6 +495,7 @@ class MyReporter { this.hooksStarted = {}; } } catch(error) { + debugOnConsole(`Exception in populating test data for event ${eventType} with error : ${error}`); debug(`Exception in populating test data for event ${eventType} with error : ${error}`, true, error); } }