From 0ad1fc35e85ae6904aca67921e0f017ae573861e Mon Sep 17 00:00:00 2001 From: Dzmitry Lemechko Date: Mon, 22 Jan 2024 19:18:10 +0200 Subject: [PATCH] [kbn/journeys] fix hanging on telemetry call & improve logging (#175194) ## Summary This PR fixes the issue causing (mostly) [login journey](https://buildkite.com/elastic/kibana-single-user-performance/builds/12398#018d1149-cc2e-4591-a61c-176768081e2c) stuck for 14 min waiting for Telemetry call response. Screenshot 2024-01-22 at 11 12 24 I believe the issue was in how we handle the Observables for request events. I added extra comment in the particular code change. I no longer can reproduce it, all the events are reported correctly: image Logs cleaning is to log in console only performance metrics event but not all EBT elements. Also not to report some browser errors that not Kibana specific. Testing: run the following script 3-4 times ``` PERFORMANCE_ENABLE_TELEMETRY=1 node scripts/run_performance.js --journey-path x-pack/performance/journeys/login.ts ``` - script is completed without delays (e.g. doesn't hang on after hook in TEST phase) - telemetry requests are logged with correct counter and all finished, e.g. `Waiting for telemetry request #2 to complete` is followed by `Telemetry request #2 complete` - only events started with `Report event "performance_metric"` are in console output --- .../journey/journey_ftr_harness.ts | 61 +++++++++++++------ .../kbn-journeys/services/page/kibana_page.ts | 4 ++ .../journeys/dashboard_listing_page.ts | 24 +++++--- .../journeys/ecommerce_dashboard.ts | 4 +- .../journeys/ecommerce_dashboard_map_only.ts | 4 +- .../ecommerce_dashboard_saved_search_only.ts | 4 +- .../ecommerce_dashboard_tsvb_gauge_only.ts | 4 +- .../performance/journeys/flight_dashboard.ts | 4 +- x-pack/performance/journeys/login.ts | 7 ++- .../journeys/many_fields_lens_editor.ts | 4 +- .../journeys/promotion_tracking_dashboard.ts | 4 +- .../journeys/web_logs_dashboard.ts | 4 +- 12 files changed, 79 insertions(+), 49 deletions(-) diff --git a/packages/kbn-journeys/journey/journey_ftr_harness.ts b/packages/kbn-journeys/journey/journey_ftr_harness.ts index 0f649e7a1de27..7becb99f3970b 100644 --- a/packages/kbn-journeys/journey/journey_ftr_harness.ts +++ b/packages/kbn-journeys/journey/journey_ftr_harness.ts @@ -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'; @@ -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() { @@ -333,33 +333,36 @@ export class JourneyFtrHarness { private telemetryTrackerCount = 0; private trackTelemetryRequests(page: Page) { - const id = ++this.telemetryTrackerCount; - - const requestFailure$ = Rx.fromEvent(page, 'requestfailed'); - const requestSuccess$ = Rx.fromEvent(page, 'requestfinished'); - const request$ = Rx.fromEvent(page, 'request').pipe( + const requestSuccess$ = Rx.fromEvent( + page, + 'requestfinished' + ) as Rx.Observable; + const request$ = (Rx.fromEvent(page, 'request') as Rx.Observable).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}`), }) ); }) @@ -446,6 +449,15 @@ 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()); @@ -453,8 +465,17 @@ export class JourneyFtrHarness { ? 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; } diff --git a/packages/kbn-journeys/services/page/kibana_page.ts b/packages/kbn-journeys/services/page/kibana_page.ts index 8a45faf1a97cc..3001d74a8e897 100644 --- a/packages/kbn-journeys/services/page/kibana_page.ts +++ b/packages/kbn-journeys/services/page/kibana_page.ts @@ -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')); } diff --git a/x-pack/performance/journeys/dashboard_listing_page.ts b/x-pack/performance/journeys/dashboard_listing_page.ts index b0afacf2cafd3..bad94790b2805 100644 --- a/x-pack/performance/journeys/dashboard_listing_page.ts +++ b/x-pack/performance/journeys/dashboard_listing_page.ts @@ -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')); @@ -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(); }); diff --git a/x-pack/performance/journeys/ecommerce_dashboard.ts b/x-pack/performance/journeys/ecommerce_dashboard.ts index 118bddc3de5cd..2de431478c848 100644 --- a/x-pack/performance/journeys/ecommerce_dashboard.ts +++ b/x-pack/performance/journeys/ecommerce_dashboard.ts @@ -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 }) => { diff --git a/x-pack/performance/journeys/ecommerce_dashboard_map_only.ts b/x-pack/performance/journeys/ecommerce_dashboard_map_only.ts index 1aeb20312505f..cbf3c5f98e2ff 100644 --- a/x-pack/performance/journeys/ecommerce_dashboard_map_only.ts +++ b/x-pack/performance/journeys/ecommerce_dashboard_map_only.ts @@ -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 }) => { diff --git a/x-pack/performance/journeys/ecommerce_dashboard_saved_search_only.ts b/x-pack/performance/journeys/ecommerce_dashboard_saved_search_only.ts index fa24cb30844ad..af9d047881545 100644 --- a/x-pack/performance/journeys/ecommerce_dashboard_saved_search_only.ts +++ b/x-pack/performance/journeys/ecommerce_dashboard_saved_search_only.ts @@ -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 }) => { diff --git a/x-pack/performance/journeys/ecommerce_dashboard_tsvb_gauge_only.ts b/x-pack/performance/journeys/ecommerce_dashboard_tsvb_gauge_only.ts index c22001896eb7c..d50860eb5f876 100644 --- a/x-pack/performance/journeys/ecommerce_dashboard_tsvb_gauge_only.ts +++ b/x-pack/performance/journeys/ecommerce_dashboard_tsvb_gauge_only.ts @@ -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 }) => { diff --git a/x-pack/performance/journeys/flight_dashboard.ts b/x-pack/performance/journeys/flight_dashboard.ts index 0ab488818d051..04867394f1be5 100644 --- a/x-pack/performance/journeys/flight_dashboard.ts +++ b/x-pack/performance/journeys/flight_dashboard.ts @@ -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 }) => { diff --git a/x-pack/performance/journeys/login.ts b/x-pack/performance/journeys/login.ts index 5cf705dec2ef9..4a602db6ae2b3 100644 --- a/x-pack/performance/journeys/login.ts +++ b/x-pack/performance/journeys/login.ts @@ -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 }); @@ -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', + }); }); diff --git a/x-pack/performance/journeys/many_fields_lens_editor.ts b/x-pack/performance/journeys/many_fields_lens_editor.ts index f14dbd17b6c23..2672d78955d28 100644 --- a/x-pack/performance/journeys/many_fields_lens_editor.ts +++ b/x-pack/performance/journeys/many_fields_lens_editor.ts @@ -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); diff --git a/x-pack/performance/journeys/promotion_tracking_dashboard.ts b/x-pack/performance/journeys/promotion_tracking_dashboard.ts index 77fed38c808d8..5217c10acae8b 100644 --- a/x-pack/performance/journeys/promotion_tracking_dashboard.ts +++ b/x-pack/performance/journeys/promotion_tracking_dashboard.ts @@ -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 }) => { diff --git a/x-pack/performance/journeys/web_logs_dashboard.ts b/x-pack/performance/journeys/web_logs_dashboard.ts index 28a80d2156900..26f05db108382 100644 --- a/x-pack/performance/journeys/web_logs_dashboard.ts +++ b/x-pack/performance/journeys/web_logs_dashboard.ts @@ -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 }) => {