Skip to content

Commit

Permalink
Merge pull request #863 from 07souravkunda/improve_o11y_timeouts
Browse files Browse the repository at this point in the history 
add: debug logs for timeout
  • Loading branch information
@pranavj1001
pranavj1001 authored Sep 3, 2024
2 parents 69bbb5a + a0b224b commit 6712cee
Show file tree
Hide file tree
Showing 2 changed files with 43 additions and 1 deletion.
19 changes: 19 additions & 0 deletions bin/testObservability/helper/helper.js
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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);
Expand Down Expand Up @@ -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}`);
Expand Down Expand Up @@ -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 {
Expand All @@ -496,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',
Expand All @@ -522,6 +536,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) {
Expand All @@ -538,7 +553,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 {
Expand All @@ -550,6 +568,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 {
Expand Down
25 changes: 24 additions & 1 deletion bin/testObservability/reporter/index.js
View file
Original file line number Diff line number Diff line change
Expand Up @@ -57,7 +57,8 @@ const {
getOSDetailsFromSystem,
findGitConfig,
getFileSeparatorData,
setCrashReportingConfigFromReporter
setCrashReportingConfigFromReporter,
debugOnConsole
} = require('../helper/helper');

const { consoleHolder } = require('../helper/constants');
Expand Down Expand Up @@ -87,13 +88,15 @@ class MyReporter {
})

.on(EVENT_HOOK_BEGIN, async (hook) => {
debugOnConsole(`[MOCHA EVENT] EVENT_HOOK_BEGIN`);
if(this.testObservability == true) {
if(!hook.hookAnalyticsId) {
hook.hookAnalyticsId = uuidv4();
} else if(this.runStatusMarkedHash[hook.hookAnalyticsId]) {
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;
Expand All @@ -102,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) {
Expand All @@ -114,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");
}
}
Expand All @@ -123,7 +130,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);
Expand All @@ -132,7 +141,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;
Expand All @@ -146,8 +157,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");
Expand All @@ -156,13 +169,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]) {
Expand All @@ -174,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");
}
}
Expand Down Expand Up @@ -318,6 +337,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 = [];
Expand Down Expand Up @@ -377,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);
}

Expand Down Expand Up @@ -473,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);
}
}
Expand Down

0 comments on commit 6712cee

Please sign in to comment.