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

dmlemeshko · 2024-01-22T10:15:55Z

Summary

This PR fixes the issue causing (mostly) login journey stuck for 14 min waiting for Telemetry call response.

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:

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

dmlemeshko · 2024-01-22T10:57:59Z

packages/kbn-journeys/journey/journey_ftr_harness.ts

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


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)

dmlemeshko · 2024-01-22T10:58:34Z

packages/kbn-journeys/services/page/kibana_page.ts

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


Moving to page object and updating tests for consistency.

dmlemeshko · 2024-01-22T10:59:03Z

x-pack/performance/journeys/login.ts

+  await page.waitForSelector(subj('userMenuButton'), {
+    state: 'attached',
+  });


Improve waiting for home page after login

dmlemeshko · 2024-01-22T11:01:25Z

/ci

kibana-ci · 2024-01-22T14:58:02Z

💚 Build Succeeded

Buildkite Build
Commit: 562bc2f

Metrics [docs]

✅ unchanged

History

💚 Build #188445 succeeded 0fcc3ba

To update your PR or re-run it, just comment with:
@elasticmachine merge upstream

cc @dmlemeshko

pheyos

LGTM

…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 (cherry picked from commit 8be528e)

kibanamachine · 2024-01-22T17:23:44Z

💚 All backports created successfully

Status	Branch	Result
✅	8.12

Note: Successful backport PRs will be merged automatically after passing CI.

Questions ?

Please refer to the Backport tool documentation

…ging (#175194) (#175247) # Backport This will backport the following commits from `main` to `8.12`: - [[kbn/journeys] fix hanging on telemetry call & improve logging (#175194)](#175194)  ### Questions ? Please refer to the [Backport tool documentation](https://github.com/sqren/backport)  Co-authored-by: Dzmitry Lemechko <dzmitry.lemechko@elastic.co>

…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

dmlemeshko added 14 commits January 17, 2024 18:27

add logs in after hook

12baf1b

update script

6db47af

update logs

1b1d2da

test fix

a136c1d

force stop kibana

0f32649

revert back script changes

e72b17c

Merge remote-tracking branch 'upstream/main' into debug-login-journey

17b461f

update waiting for dashboard list view

7895c47

remove extra logging

e770753

clean console logs

f64a4e3

remove commented code

49172aa

more logs cleanup

0a0e48a

Merge remote-tracking branch 'upstream/main' into debug-login-journey

f51ee2b

revert SIGKILL for kibana poc

0fcc3ba

dmlemeshko commented Jan 22, 2024

View reviewed changes

dmlemeshko self-assigned this Jan 22, 2024

dmlemeshko added release_note:skip Skip the PR/issue when compiling release notes v8.12.1 v8.13.0 labels Jan 22, 2024

dmlemeshko marked this pull request as ready for review January 22, 2024 13:00

dmlemeshko requested review from a team as code owners January 22, 2024 13:00

dmlemeshko added 2 commits January 22, 2024 14:29

fix logging events to console

beb0b99

restore log

7dc16c3

jbudz approved these changes Jan 22, 2024

View reviewed changes

fix deprecation warnings

562bc2f

dmlemeshko mentioned this pull request Jan 22, 2024

[ci] increase timeout for performance pipeline step to 90 min #175044

Merged

pheyos approved these changes Jan 22, 2024

View reviewed changes

dmlemeshko merged commit 8be528e into elastic:main Jan 22, 2024
17 checks passed

kibanamachine mentioned this pull request Jan 22, 2024

[8.12] [kbn/journeys] fix hanging on telemetry call & improve logging (#175194) #175247

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

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

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

dmlemeshko commented Jan 22, 2024 •

edited by kibanamachine

Loading

dmlemeshko Jan 22, 2024 •

edited

Loading

dmlemeshko Jan 22, 2024

dmlemeshko Jan 22, 2024

dmlemeshko commented Jan 22, 2024

kibana-ci commented Jan 22, 2024

pheyos left a comment

kibanamachine commented Jan 22, 2024

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

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

Conversation

dmlemeshko commented Jan 22, 2024 • edited by kibanamachine Loading

Summary

dmlemeshko Jan 22, 2024 • edited Loading

Choose a reason for hiding this comment

dmlemeshko Jan 22, 2024

Choose a reason for hiding this comment

dmlemeshko Jan 22, 2024

Choose a reason for hiding this comment

dmlemeshko commented Jan 22, 2024

kibana-ci commented Jan 22, 2024

💚 Build Succeeded

Metrics [docs]

History

pheyos left a comment

Choose a reason for hiding this comment

kibanamachine commented Jan 22, 2024

💚 All backports created successfully

Questions ?

dmlemeshko commented Jan 22, 2024 •

edited by kibanamachine

Loading

dmlemeshko Jan 22, 2024 •

edited

Loading