[kbn/journeys] fix hanging on telemetry call & improve logging (elast…

…ic#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.


<img width="964" alt="Screenshot 2024-01-22 at 11 12 24"
src="https://github.com/elastic/kibana/assets/10977896/8cadc2ec-ee84-42f6-8a0c-ad949367429c">

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:
<img width="964" alt="image"
src="https://github.com/elastic/kibana/assets/10977896/fa2c4b27-dcf2-480b-a07f-aeb23045149a">

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 elastic#2 to complete` is followed by
`Telemetry request elastic#2 complete`
- only events started with `Report event "performance_metric"` are in
console output

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<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}`),
           })
         );
       })
@@ -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;
       }
 

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'));
   }

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();
   });

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 }) => {

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 }) => {

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 }) => {

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 }) => {

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 }) => {

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',
+  });
 });

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);

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 }) => {

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 }) => {