Skip to content

add: debug logs for timeout #863

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
merged 3 commits into from
Sep 3, 2024
Merged

add: debug logs for timeout #863

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
3 commits
Select commit Hold shift + click to select a range
eedd758
add: debug logs for timeout
07souravkunda Aug 28, 2024
5e9257c
Merge branch 'master' into improve_o11y_timeouts
07souravkunda Aug 28, 2024
a0b224b
chore: comments
07souravkunda Aug 30, 2024
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
19 changes: 19 additions & 0 deletions bin/testObservability/helper/helper.js
View file
Open in desktop
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
Open in desktop
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
Loading