Skip to content
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

[kbn/journeys] fix hanging on telemetry call & improve logging #175194

Merged
merged 17 commits into from
Jan 22, 2024
Merged

[kbn/journeys] fix hanging on telemetry call & improve logging #175194

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
17 commits
Select commit Hold shift + click to select a range
12baf1b
add logs in after hook
dmlemeshko Jan 17, 2024
6db47af
update script
dmlemeshko Jan 17, 2024
1b1d2da
update logs
dmlemeshko Jan 18, 2024
a136c1d
test fix
dmlemeshko Jan 18, 2024
0f32649
force stop kibana
dmlemeshko Jan 19, 2024
e72b17c
revert back script changes
dmlemeshko Jan 19, 2024
17b461f
Merge remote-tracking branch 'upstream/main' into debug-login-journey
dmlemeshko Jan 21, 2024
7895c47
update waiting for dashboard list view
dmlemeshko Jan 21, 2024
e770753
remove extra logging
dmlemeshko Jan 21, 2024
f64a4e3
clean console logs
dmlemeshko Jan 22, 2024
49172aa
remove commented code
dmlemeshko Jan 22, 2024
0a0e48a
more logs cleanup
dmlemeshko Jan 22, 2024
f51ee2b
Merge remote-tracking branch 'upstream/main' into debug-login-journey
dmlemeshko Jan 22, 2024
0fcc3ba
revert SIGKILL for kibana poc
dmlemeshko Jan 22, 2024
beb0b99
fix logging events to console
dmlemeshko Jan 22, 2024
7dc16c3
restore log
dmlemeshko Jan 22, 2024
562bc2f
fix deprecation warnings
dmlemeshko Jan 22, 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
61 changes: 41 additions & 20 deletions packages/kbn-journeys/journey/journey_ftr_harness.ts
View file
Open in desktop
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}`),
Comment on lines +352 to +365
Copy link
Member Author

@dmlemeshko dmlemeshko Jan 22, 2024 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I made a few changes to make it work correctly:

  • telemetryTrackerCount was always returning 1 since it was misplaced before observables.
  • delete requestFailure$ since we don't have to do anything in case of Telemetry request failure event. We fully rely on kibana service to make things the right way.
  • adding timeout of 60 sec to issue error notification in case of no new emitted events;
  • log messages on both complete & error
 └-> Go to Transform Wizard
     └-> "before each" hook: global before each for "Go to Transform Wizard"
     │ debg APM DEBUG start span {"span":"fe0fad39231fa33e","parent":"9cf0f1c9d8df9a6a","trace":"ada4a00b5cac22401cd1ed060e28e4f2","name":"step: Go to Transform Wizard","type":"step","subtype":null,"action":null}
     │ debg APM DEBUG supersedeWithSpanRunContext(<Span fe0fad39231fa33e>)
     │ info Waiting for telemetry request #2 to complete
     │ info Telemetry request #2 complete
     │ info Waiting for telemetry request #3 to complete
     │ info Telemetry request #3 complete
     │ info Waiting for telemetry request #4 to complete
     │ info Telemetry request #4 complete
     │ debg APM DEBUG ended span {"span":"fe0fad39231fa33e","parent":"9cf0f1c9d8df9a6a","trace":"ada4a00b5cac22401cd1ed060e28e4f2","name":"step: Go to Transform Wizard","type":"step","subtype":null,"action":null}
     │ debg APM DEBUG addEndedSpan(step: Go to Transform Wizard)
     │ debg APM DEBUG encoding span {"span":"fe0fad39231fa33e","parent":"9cf0f1c9d8df9a6a","trace":"ada4a00b5cac22401cd1ed060e28e4f2","name":"step: Go to Transform Wizard","type":"step"}
     └- ✓ pass  (1.0m)

})
);
})
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
View file
Open in desktop
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' });
}
Comment on lines +39 to +41
Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Moving to page object and updating tests for consistency.


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
View file
Open in desktop
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
View file
Open in desktop
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
View file
Open in desktop
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
4 changes: 2 additions & 2 deletions x-pack/performance/journeys/ecommerce_dashboard_saved_search_only.ts
View file
Open in desktop
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
4 changes: 2 additions & 2 deletions x-pack/performance/journeys/ecommerce_dashboard_tsvb_gauge_only.ts
View file
Open in desktop
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
View file
Open in desktop
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
View file
Open in desktop
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',
});
Comment on lines +45 to +47
Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Improve waiting for home page after login

});
4 changes: 2 additions & 2 deletions x-pack/performance/journeys/many_fields_lens_editor.ts
View file
Open in desktop
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
View file
Open in desktop
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
View file
Open in desktop
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