Skip to content

Commit

Permalink
[8.12] [kbn/journeys] fix hanging on telemetry call & improve log…
Browse files Browse the repository at this point in the history
…ging (elastic#175194) (elastic#175247)

# Backport

This will backport the following commits from `main` to `8.12`:
- [[kbn/journeys] fix hanging on telemetry call & improve logging
(elastic#175194)](elastic#175194)

<!--- Backport version: 9.4.3 -->

### Questions ?
Please refer to the [Backport tool
documentation](https://github.com/sqren/backport)

<!--BACKPORT [{"author":{"name":"Dzmitry
Lemechko","email":"[email protected]"},"sourceCommit":{"committedDate":"2024-01-22T17:18:10Z","message":"[kbn/journeys]
fix hanging on telemetry call & improve logging (elastic#175194)\n\n##
Summary\r\n\r\nThis PR fixes the issue causing (mostly)
[login\r\njourney](https://buildkite.com/elastic/kibana-single-user-performance/builds/12398#018d1149-cc2e-4591-a61c-176768081e2c)\r\nstuck
for 14 min waiting for Telemetry call response.\r\n\r\n\r\n<img
width=\"964\" alt=\"Screenshot 2024-01-22 at 11 12
24\"\r\nsrc=\"https://github.com/elastic/kibana/assets/10977896/8cadc2ec-ee84-42f6-8a0c-ad949367429c\">\r\n\r\nI
believe the issue was in how we handle the Observables for
request\r\nevents. I added extra comment in the particular code
change.\r\n\r\nI no longer can reproduce it, all the events are reported
correctly:\r\n<img width=\"964\"
alt=\"image\"\r\nsrc=\"https://github.com/elastic/kibana/assets/10977896/fa2c4b27-dcf2-480b-a07f-aeb23045149a\">\r\n\r\nLogs
cleaning is to log in console only performance metrics event but\r\nnot
all EBT elements. Also not to report some browser errors that
not\r\nKibana specific.\r\n\r\n\r\nTesting:\r\n\r\nrun the following
script 3-4 times\r\n```\r\nPERFORMANCE_ENABLE_TELEMETRY=1 node
scripts/run_performance.js --journey-path
x-pack/performance/journeys/login.ts\r\n```\r\n\r\n- script is completed
without delays (e.g. doesn't hang on after hook in\r\nTEST phase)\r\n-
telemetry requests are logged with correct counter and all
finished,\r\ne.g. `Waiting for telemetry request #2 to complete` is
followed by\r\n`Telemetry request #2 complete`\r\n- only events started
with `Report event \"performance_metric\"` are in\r\nconsole
output","sha":"8be528efb3169b630f44b33912adaf63bdea2a25","branchLabelMapping":{"^v8.13.0$":"main","^v(\\d+).(\\d+).\\d+$":"$1.$2"}},"sourcePullRequest":{"labels":["release_note:skip","v8.12.1","v8.13.0"],"title":"[kbn/journeys]
fix hanging on telemetry call & improve
logging","number":175194,"url":"https://github.com/elastic/kibana/pull/175194","mergeCommit":{"message":"[kbn/journeys]
fix hanging on telemetry call & improve logging (elastic#175194)\n\n##
Summary\r\n\r\nThis PR fixes the issue causing (mostly)
[login\r\njourney](https://buildkite.com/elastic/kibana-single-user-performance/builds/12398#018d1149-cc2e-4591-a61c-176768081e2c)\r\nstuck
for 14 min waiting for Telemetry call response.\r\n\r\n\r\n<img
width=\"964\" alt=\"Screenshot 2024-01-22 at 11 12
24\"\r\nsrc=\"https://github.com/elastic/kibana/assets/10977896/8cadc2ec-ee84-42f6-8a0c-ad949367429c\">\r\n\r\nI
believe the issue was in how we handle the Observables for
request\r\nevents. I added extra comment in the particular code
change.\r\n\r\nI no longer can reproduce it, all the events are reported
correctly:\r\n<img width=\"964\"
alt=\"image\"\r\nsrc=\"https://github.com/elastic/kibana/assets/10977896/fa2c4b27-dcf2-480b-a07f-aeb23045149a\">\r\n\r\nLogs
cleaning is to log in console only performance metrics event but\r\nnot
all EBT elements. Also not to report some browser errors that
not\r\nKibana specific.\r\n\r\n\r\nTesting:\r\n\r\nrun the following
script 3-4 times\r\n```\r\nPERFORMANCE_ENABLE_TELEMETRY=1 node
scripts/run_performance.js --journey-path
x-pack/performance/journeys/login.ts\r\n```\r\n\r\n- script is completed
without delays (e.g. doesn't hang on after hook in\r\nTEST phase)\r\n-
telemetry requests are logged with correct counter and all
finished,\r\ne.g. `Waiting for telemetry request #2 to complete` is
followed by\r\n`Telemetry request #2 complete`\r\n- only events started
with `Report event \"performance_metric\"` are in\r\nconsole
output","sha":"8be528efb3169b630f44b33912adaf63bdea2a25"}},"sourceBranch":"main","suggestedTargetBranches":["8.12"],"targetPullRequestStates":[{"branch":"8.12","label":"v8.12.1","branchLabelMappingKey":"^v(\\d+).(\\d+).\\d+$","isSourceBranch":false,"state":"NOT_CREATED"},{"branch":"main","label":"v8.13.0","branchLabelMappingKey":"^v8.13.0$","isSourceBranch":true,"state":"MERGED","url":"https://github.com/elastic/kibana/pull/175194","number":175194,"mergeCommit":{"message":"[kbn/journeys]
fix hanging on telemetry call & improve logging (elastic#175194)\n\n##
Summary\r\n\r\nThis PR fixes the issue causing (mostly)
[login\r\njourney](https://buildkite.com/elastic/kibana-single-user-performance/builds/12398#018d1149-cc2e-4591-a61c-176768081e2c)\r\nstuck
for 14 min waiting for Telemetry call response.\r\n\r\n\r\n<img
width=\"964\" alt=\"Screenshot 2024-01-22 at 11 12
24\"\r\nsrc=\"https://github.com/elastic/kibana/assets/10977896/8cadc2ec-ee84-42f6-8a0c-ad949367429c\">\r\n\r\nI
believe the issue was in how we handle the Observables for
request\r\nevents. I added extra comment in the particular code
change.\r\n\r\nI no longer can reproduce it, all the events are reported
correctly:\r\n<img width=\"964\"
alt=\"image\"\r\nsrc=\"https://github.com/elastic/kibana/assets/10977896/fa2c4b27-dcf2-480b-a07f-aeb23045149a\">\r\n\r\nLogs
cleaning is to log in console only performance metrics event but\r\nnot
all EBT elements. Also not to report some browser errors that
not\r\nKibana specific.\r\n\r\n\r\nTesting:\r\n\r\nrun the following
script 3-4 times\r\n```\r\nPERFORMANCE_ENABLE_TELEMETRY=1 node
scripts/run_performance.js --journey-path
x-pack/performance/journeys/login.ts\r\n```\r\n\r\n- script is completed
without delays (e.g. doesn't hang on after hook in\r\nTEST phase)\r\n-
telemetry requests are logged with correct counter and all
finished,\r\ne.g. `Waiting for telemetry request #2 to complete` is
followed by\r\n`Telemetry request #2 complete`\r\n- only events started
with `Report event \"performance_metric\"` are in\r\nconsole
output","sha":"8be528efb3169b630f44b33912adaf63bdea2a25"}}]}]
BACKPORT-->

Co-authored-by: Dzmitry Lemechko <[email protected]>
  • Loading branch information
kibanamachine and dmlemeshko authored Jan 22, 2024
1 parent 490e1e4 commit 31a3255
Show file tree
Hide file tree
Showing 12 changed files with 79 additions and 49 deletions.
61 changes: 41 additions & 20 deletions packages/kbn-journeys/journey/journey_ftr_harness.ts
Original file line number Diff line number Diff line change
Expand Up @@ -8,7 +8,7 @@

import Url from 'url';
import { inspect, format } from 'util';
import { setTimeout } from 'timers/promises';
import { setTimeout as setTimer } from 'timers/promises';
import * as Rx from 'rxjs';
import apmNode from 'elastic-apm-node';
import playwright, { ChromiumBrowser, Page, BrowserContext, CDPSession, Request } from 'playwright';
Expand Down Expand Up @@ -222,7 +222,7 @@ export class JourneyFtrHarness {
// can't track but hope it is started within 3 seconds, node will stay
// alive for active requests
// https://github.com/elastic/apm-agent-nodejs/issues/2088
await setTimeout(3000);
await setTimer(3000);
}

private async onTeardown() {
Expand Down Expand Up @@ -333,33 +333,36 @@ export class JourneyFtrHarness {
private telemetryTrackerCount = 0;

private trackTelemetryRequests(page: Page) {
const id = ++this.telemetryTrackerCount;

const requestFailure$ = Rx.fromEvent<Request>(page, 'requestfailed');
const requestSuccess$ = Rx.fromEvent<Request>(page, 'requestfinished');
const request$ = Rx.fromEvent<Request>(page, 'request').pipe(
const requestSuccess$ = Rx.fromEvent(
page,
'requestfinished'
) as Rx.Observable<playwright.Request>;
const request$ = (Rx.fromEvent(page, 'request') as Rx.Observable<playwright.Request>).pipe(
Rx.takeUntil(
this.pageTeardown$.pipe(
Rx.first((p) => p === page),
Rx.delay(3000)
// If EBT client buffers:
// Rx.mergeMap(async () => {
// await page.waitForFunction(() => {
// // return window.kibana_ebt_client.buffer_size == 0
// });
// })
)
),
Rx.mergeMap((request) => {
Rx.mergeMap((request: Request) => {
if (!request.url().includes('telemetry-staging.elastic.co')) {
return Rx.EMPTY;
}

this.log.debug(`Waiting for telemetry request #${id} to complete`);
return Rx.merge(requestFailure$, requestSuccess$).pipe(
Rx.first((r) => r === request),
const id = ++this.telemetryTrackerCount;
this.log.info(`Waiting for telemetry request #${id} to complete`);
return Rx.of(requestSuccess$).pipe(
Rx.timeout(60_000),
Rx.catchError((error) => {
if (error instanceof Error && error.name === 'TimeoutError') {
this.log.error(`Timeout error occurred: ${error.message}`);
}
// Rethrow the error if it's not a TimeoutError
return Rx.throwError(() => new Error(error));
}),
Rx.tap({
complete: () => this.log.debug(`Telemetry request #${id} complete`),
complete: () => this.log.info(`Telemetry request #${id} complete`),
error: (err) => this.log.error(`Telemetry request was not processed: ${err.message}`),
})
);
})
Expand Down Expand Up @@ -446,15 +449,33 @@ export class JourneyFtrHarness {
private onConsoleEvent = async (message: playwright.ConsoleMessage) => {
try {
const { url, lineNumber, columnNumber } = message.location();

if (
url.includes('kbn-ui-shared-deps-npm.dll.js') ||
url.includes('kbn-ui-shared-deps-src.js')
) {
// ignore messages from kbn-ui-shared-deps-npm.dll.js & kbn-ui-shared-deps-src.js
return;
}

const location = `${url}:${lineNumber}:${columnNumber}`;

const args = await asyncMap(message.args(), (handle) => handle.jsonValue());
const text = args.length
? args.map((arg) => (typeof arg === 'string' ? arg : inspect(arg, false, null))).join(' ')
: message.text();

if (url.includes('kbn-ui-shared-deps-npm.dll.js')) {
// ignore errors/warning from kbn-ui-shared-deps-npm.dll.js
if (text.includes(`Unrecognized feature: 'web-share'`)) {
// ignore Error with Permissions-Policy header: Unrecognized feature: 'web-share'
return;
}

if (
url.includes('core.entry.js') &&
args.length > 1 &&
!('performance_metric' === args[1]?.ebt_event?.event_type)
) {
// ignore events like "click", log to console only 'event_type: performance_metric'
return;
}

Expand Down
4 changes: 4 additions & 0 deletions packages/kbn-journeys/services/page/kibana_page.ts
Original file line number Diff line number Diff line change
Expand Up @@ -36,6 +36,10 @@ export class KibanaPage {
});
}

async waitForListViewTable() {
await this.page.waitForSelector(subj('table-is-ready'), { state: 'visible' });
}

async backToDashboardListing() {
await this.page.click(subj('breadcrumb dashboardListingBreadcrumb first'));
}
Expand Down
24 changes: 14 additions & 10 deletions x-pack/performance/journeys/dashboard_listing_page.ts
Original file line number Diff line number Diff line change
Expand Up @@ -16,21 +16,25 @@ export const journey = new Journey({
'x-pack/performance/kbn_archives/logs_no_map_dashboard',
],
})
.step('Go to Dashboards Page', async ({ page, kbnUrl }) => {
.step('Go to Dashboards Page', async ({ page, kbnUrl, kibanaPage }) => {
await page.goto(kbnUrl.get(`/app/dashboards`));
await page.waitForSelector(subj('table-is-ready'));
await kibanaPage.waitForListViewTable();
})
.step('Search dashboards', async ({ page, inputDelays }) => {
.step('Search dashboards', async ({ page, inputDelays, kibanaPage }) => {
await page.type(subj('tableListSearchBox'), 'Web', {
delay: inputDelays.TYPING,
});
await page.waitForSelector(subj('table-is-ready'));
await kibanaPage.waitForListViewTable();
})
.step('Delete dashboard', async ({ page }) => {
await page.click(subj('checkboxSelectRow-edf84fe0-e1a0-11e7-b6d5-4dc382ef7f5b'));
.step('Delete dashboard', async ({ page, kibanaPage }) => {
const deletedDashboard = page.locator(
subj('checkboxSelectRow-edf84fe0-e1a0-11e7-b6d5-4dc382ef7f5b')
);
await deletedDashboard.click();
await page.click(subj('deleteSelectedItems'));
await page.click(subj('confirmModalConfirmButton'));
await page.waitForSelector(subj('table-is-ready'));
await kibanaPage.waitForListViewTable();
await deletedDashboard.waitFor({ state: 'detached' });
})
.step('Add dashboard', async ({ page, inputDelays }) => {
await page.click(subj('newItemButton'));
Expand All @@ -41,7 +45,7 @@ export const journey = new Journey({
await page.click(subj('confirmSaveSavedObjectButton'));
await page.waitForSelector(subj('saveDashboardSuccess'));
})
.step('Return to dashboard list', async ({ kibanaPage, page }) => {
kibanaPage.backToDashboardListing();
await page.waitForSelector(subj('table-is-ready'));
.step('Return to dashboard list', async ({ kibanaPage }) => {
await kibanaPage.backToDashboardListing();
await kibanaPage.waitForListViewTable();
});
4 changes: 2 additions & 2 deletions x-pack/performance/journeys/ecommerce_dashboard.ts
Original file line number Diff line number Diff line change
Expand Up @@ -13,9 +13,9 @@ export const journey = new Journey({
kbnArchives: ['x-pack/performance/kbn_archives/ecommerce_no_map_dashboard'],
})

.step('Go to Dashboards Page', async ({ page, kbnUrl }) => {
.step('Go to Dashboards Page', async ({ page, kbnUrl, kibanaPage }) => {
await page.goto(kbnUrl.get(`/app/dashboards`));
await page.waitForSelector('#dashboardListingHeading');
await kibanaPage.waitForListViewTable();
})

.step('Go to Ecommerce Dashboard', async ({ page, kibanaPage }) => {
Expand Down
4 changes: 2 additions & 2 deletions x-pack/performance/journeys/ecommerce_dashboard_map_only.ts
Original file line number Diff line number Diff line change
Expand Up @@ -13,9 +13,9 @@ export const journey = new Journey({
kbnArchives: ['x-pack/performance/kbn_archives/ecommerce_map_only_dashboard'],
})

.step('Go to Dashboards Page', async ({ page, kbnUrl }) => {
.step('Go to Dashboards Page', async ({ page, kbnUrl, kibanaPage }) => {
await page.goto(kbnUrl.get(`/app/dashboards`));
await page.waitForSelector('#dashboardListingHeading');
await kibanaPage.waitForListViewTable();
})

.step('Go to Ecommerce No Map Dashboard', async ({ page }) => {
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -13,9 +13,9 @@ export const journey = new Journey({
kbnArchives: ['x-pack/performance/kbn_archives/ecommerce_saved_search_only_dashboard'],
})

.step('Go to Dashboards Page', async ({ page, kbnUrl }) => {
.step('Go to Dashboards Page', async ({ page, kbnUrl, kibanaPage }) => {
await page.goto(kbnUrl.get(`/app/dashboards`));
await page.waitForSelector('#dashboardListingHeading');
await kibanaPage.waitForListViewTable();
})

.step('Go to Ecommerce Dashboard with Saved Search only', async ({ page, kibanaPage }) => {
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -13,9 +13,9 @@ export const journey = new Journey({
kbnArchives: ['x-pack/performance/kbn_archives/ecommerce_tsvb_gauge_only_dashboard'],
})

.step('Go to Dashboards Page', async ({ page, kbnUrl }) => {
.step('Go to Dashboards Page', async ({ page, kbnUrl, kibanaPage }) => {
await page.goto(kbnUrl.get(`/app/dashboards`));
await page.waitForSelector('#dashboardListingHeading');
await kibanaPage.waitForListViewTable();
})

.step('Go to Ecommerce Dashboard with TSVB Gauge only', async ({ page, kibanaPage }) => {
Expand Down
4 changes: 2 additions & 2 deletions x-pack/performance/journeys/flight_dashboard.ts
Original file line number Diff line number Diff line change
Expand Up @@ -13,9 +13,9 @@ export const journey = new Journey({
kbnArchives: ['x-pack/performance/kbn_archives/flights_no_map_dashboard'],
})

.step('Go to Dashboards Page', async ({ page, kbnUrl }) => {
.step('Go to Dashboards Page', async ({ page, kbnUrl, kibanaPage }) => {
await page.goto(kbnUrl.get(`/app/dashboards`));
await page.waitForSelector('#dashboardListingHeading');
await kibanaPage.waitForListViewTable();
})

.step('Go to Flights Dashboard', async ({ page, kibanaPage }) => {
Expand Down
7 changes: 4 additions & 3 deletions x-pack/performance/journeys/login.ts
Original file line number Diff line number Diff line change
Expand Up @@ -33,7 +33,7 @@ export const journey = new Journey({
],
maxDuration: '10m',
},
}).step('Login', async ({ page, kbnUrl, inputDelays, auth, kibanaPage }) => {
}).step('Login', async ({ page, kbnUrl, inputDelays, auth }) => {
await page.goto(kbnUrl.get());
if (auth.isCloud()) {
await page.click(subj('loginCard-basic/cloud-basic'), { delay: inputDelays.MOUSE_CLICK });
Expand All @@ -42,6 +42,7 @@ export const journey = new Journey({
await page.type(subj('loginUsername'), auth.getUsername(), { delay: inputDelays.TYPING });
await page.type(subj('loginPassword'), auth.getPassword(), { delay: inputDelays.TYPING });
await page.click(subj('loginSubmit'), { delay: inputDelays.MOUSE_CLICK });

await kibanaPage.waitForHeader();
await page.waitForSelector(subj('userMenuButton'), {
state: 'attached',
});
});
4 changes: 2 additions & 2 deletions x-pack/performance/journeys/many_fields_lens_editor.ts
Original file line number Diff line number Diff line change
Expand Up @@ -13,13 +13,13 @@ export const journey = new Journey({
kbnArchives: ['x-pack/performance/kbn_archives/lens_many_fields'],
esArchives: ['test/functional/fixtures/es_archiver/stress_test'],
})
.step('Go to Visualize Library landing page', async ({ page, kbnUrl }) => {
.step('Go to Visualize Library landing page', async ({ page, kbnUrl, kibanaPage }) => {
await page.goto(
kbnUrl.get(
`/app/visualize#/?_g=(filters:!(),time:(from:'2022-09-07T10:53:30.262Z',to:'2022-09-07T10:55:09.280Z'))`
)
);
await page.waitForSelector(subj('table-is-ready'));
await kibanaPage.waitForListViewTable();
// wait extra 10 seconds: we're not sure why, but the extra sleep before loading the editor makes the metrics more consistent
// sometimes lens charts are not loaded
await page.waitForTimeout(10000);
Expand Down
4 changes: 2 additions & 2 deletions x-pack/performance/journeys/promotion_tracking_dashboard.ts
Original file line number Diff line number Diff line change
Expand Up @@ -35,9 +35,9 @@ export const journey = new Journey({
maxDuration: '10m',
},
})
.step('Go to Dashboards Page', async ({ page, kbnUrl }) => {
.step('Go to Dashboards Page', async ({ page, kbnUrl, kibanaPage }) => {
await page.goto(kbnUrl.get(`/app/dashboards`));
await page.waitForSelector('#dashboardListingHeading');
await kibanaPage.waitForListViewTable();
})

.step('Go to Promotion Tracking Dashboard', async ({ page }) => {
Expand Down
4 changes: 2 additions & 2 deletions x-pack/performance/journeys/web_logs_dashboard.ts
Original file line number Diff line number Diff line change
Expand Up @@ -13,9 +13,9 @@ export const journey = new Journey({
kbnArchives: ['x-pack/performance/kbn_archives/logs_no_map_dashboard'],
})

.step('Go to Dashboards Page', async ({ page, kbnUrl }) => {
.step('Go to Dashboards Page', async ({ page, kbnUrl, kibanaPage }) => {
await page.goto(kbnUrl.get(`/app/dashboards`));
await page.waitForSelector('#dashboardListingHeading');
await kibanaPage.waitForListViewTable();
})

.step('Go to Web Logs Dashboard', async ({ page, kibanaPage }) => {
Expand Down

0 comments on commit 31a3255

Please sign in to comment.