mirror of
https://github.com/elastic/kibana.git
synced 2025-04-24 09:48:58 -04:00
# Backport This will backport the following commits from `main` to `8.12`: - [[kbn/journeys] fix hanging on telemetry call & improve logging (#175194)](https://github.com/elastic/kibana/pull/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":"dzmitry.lemechko@elastic.co"},"sourceCommit":{"committedDate":"2024-01-22T17:18:10Z","message":"[kbn/journeys] fix hanging on telemetry call & improve logging (#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=\"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=\"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 (#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=\"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=\"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 (#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=\"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=\"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 <dzmitry.lemechko@elastic.co>
This commit is contained in:
parent
490e1e4d9a
commit
31a32557eb
12 changed files with 79 additions and 49 deletions
|
@ -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,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;
|
||||
}
|
||||
|
||||
|
|
|
@ -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'));
|
||||
}
|
||||
|
|
|
@ -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();
|
||||
});
|
||||
|
|
|
@ -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 }) => {
|
||||
|
|
|
@ -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 }) => {
|
||||
|
|
|
@ -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 }) => {
|
||||
|
|
|
@ -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 }) => {
|
||||
|
|
|
@ -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 }) => {
|
||||
|
|
|
@ -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',
|
||||
});
|
||||
});
|
||||
|
|
|
@ -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);
|
||||
|
|
|
@ -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 }) => {
|
||||
|
|
|
@ -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 }) => {
|
||||
|
|
Loading…
Add table
Add a link
Reference in a new issue