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.

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

[Reporting] Better logging for waitForSelector failure #25762

Merged
merged 18 commits into from
Nov 27, 2018

Conversation

tsullivan
Copy link
Member

@tsullivan tsullivan commented Nov 15, 2018

Part of #25665

Summary

If a headless browser fails because the expected page couldn't be opened, we detect that by trying to find a CSS selector, for example:.application. The error handling and messaging from the headless browser take over if that fails. That is pretty useless because we'll be told that there was a timeout looking for the selector when the real problem is the page failed to load.

This change adds more logging:

  • The page URL that failed, so we can see if we got redirected to the Login page
  • The text of the page, so we can see if Kibana is showing full-screen error instead of the actual UI

Initially, this page changes the application class on the main HTML template, so we can check reporting failures in Jenkins to ensure they make more sense

@tsullivan tsullivan added WIP Work in progress v7.0.0 (Deprecated) Feature:Reporting Use Reporting:Screenshot, Reporting:CSV, or Reporting:Framework instead v6.6.0 labels Nov 15, 2018
@tsullivan tsullivan changed the title Reporting/logging wait for selector [Reporting] Better logging for waitForSelector failure Nov 15, 2018
@elasticmachine
Copy link
Contributor

💔 Build Failed

@tsullivan
Copy link
Member Author

tsullivan commented Nov 16, 2018

A forced failure experiment shows some nice error and debugging output for a failed Chromium-generated report ...

Edit: see #25762 (comment)

@elasticmachine
Copy link
Contributor

💔 Build Failed

@elasticmachine
Copy link
Contributor

💔 Build Failed

@elasticmachine
Copy link
Contributor

💔 Build Failed

@tsullivan
Copy link
Member Author

Will log all the plain text found on the page, when a job has to retry because a selector wasn't found. The lines of text are joined into one log line. Example:

23:05:09              ? proc [kibana]   log   [23:05:09.337] [error][chromium-driver-factory][headless-chromium-driver][reporting] waitForSelector .application failed on http://localhost:5620/app/kibana#/dashboard/61c58ad0-3dd3-11e8-b2b9-5d5dc1715159?_g=(refreshInterval:(display:Off,pause:!f,value:0),time:(from:'Mon%20Apr%2009%202018%2017:56:08%20GMT-0400',mode:absolute,to:'Wed%20Apr%2011%202018%2017:56:08%20GMT-0400'))&_a=(description:'',filters:!(('$state':(store:appState),meta:(alias:!n,disabled:!f,index:a0f483a0-3dc9-11e8-8660-4d65aa086b3c,key:animal,negate:!f,params:(query:dog,type:phrase),type:phrase,value:dog),query:(match:(animal:(query:dog,type:phrase))))),fullScreenMode:!f,options:(darkTheme:!f,hidePanelTitles:!f,useMargins:!t),panels:!((embeddableConfig:(),gridData:(h:15,i:'1',w:24,x:0,y:0),id:'50643b60-3dd3-11e8-b2b9-5d5dc1715159',panelIndex:'1',type:visualization,version:'6.3.0'),(embeddableConfig:(),gridData:(h:15,i:'2',w:24,x:24,y:0),id:a16d1990-3dca-11e8-8660-4d65aa086b3c,panelIndex:'2',type:search,version:'6.3.0')),query:(language:lucene,query:''),timeRestore:!t,title:'dashboard%20with%20filter',viewMode:view)&forceNow=2018-11-16T23:04:35.906Z
23:05:09              ? proc [kibana]   log   [23:05:09.342] [debug][chromium-driver-factory][headless-chromium-driver][reporting] Page plain text: Discover\nVisualize\nDashboard\nTimelion\nCanvas\nMachine Learning\nInfrastructure\nLogs\nAPM\nGraph\nDev Tools\nMonitoring\nManagement\nelastic\nLogout\nCollapse\nDashboard\ndashboard with filter\nFull screen\nShare\nClone\nEdit\nAuto-refresh\nApril 9th 2018, 21:56:08.000 to April 11th 2018, 21:56:08.000\nOptions\nRefresh\nanimal: "dog"\nAdd a filter\nActions\nRendering Test: animal sounds pie\nPie visualization, not yet accessible\ngrrr\nruff\nbark\nbow ow ow\nanimal weights\n1Ð1 of 1\n	Time	animal	isDog	name	sound	weightLbs\n	April 10th 2018, 18:00:00.000\n	dog\n	true\n	Fee Fee\n	bark\n	43.0\n\n\n1Ð1 of 1
23:05:09              ? proc [kibana]   log   [23:05:09.366] [esqueue][reporting][warn][worker] jokmrezw037v4919629x1fh8 - Failure occurred on job jokms0g2037v4919626kr7c5: TimeoutError: waiting for selector ".application" failed: timeout 30000ms exceeded
23:05:09              ? proc [kibana]     at new WaitTask (/var/lib/jenkins/workspace/elastic+kibana+pull-request/JOB/x-pack/node/immutable/install/kibana/node_modules/puppeteer-core/lib/FrameManager.js:864:28)
23:05:09              ? proc [kibana]     at Frame._waitForSelectorOrXPath (/var/lib/jenkins/workspace/elastic+kibana+pull-request/JOB/x-pack/node/immutable/install/kibana/node_modules/puppeteer-core/lib/FrameManager.js:755:12)
23:05:09              ? proc [kibana]     at Frame.waitForSelector (/var/lib/jenkins/workspace/elastic+kibana+pull-request/JOB/x-pack/node/immutable/install/kibana/node_modules/puppeteer-core/lib/FrameManager.js:713:17)
23:05:09              ? proc [kibana]     at Frame.waitFor (/var/lib/jenkins/workspace/elastic+kibana+pull-request/JOB/x-pack/node/immutable/install/kibana/node_modules/puppeteer-core/lib/FrameManager.js:698:19)
23:05:09              ? proc [kibana]     at Page.waitFor (/var/lib/jenkins/workspace/elastic+kibana+pull-request/JOB/x-pack/node/immutable/install/kibana/node_modules/puppeteer-core/lib/Page.js:1008:29)
23:05:09              ? proc [kibana]     at HeadlessChromiumDriver.waitForSelector (/var/lib/jenkins/workspace/elastic+kibana+pull-request/JOB/x-pack/node/immutable/install/kibana/node_modules/x-pack/plugins/reporting/server/browsers/chromium/driver/chromium_driver.js:61:36)
23:05:09              ? proc [kibana]     at HeadlessChromiumDriver.open (/var/lib/jenkins/workspace/elastic+kibana+pull-request/JOB/x-pack/node/immutable/install/kibana/node_modules/x-pack/plugins/reporting/server/browsers/chromium/driver/chromium_driver.js:34:20)
23:05:09              ? proc [kibana]     at <anonymous>
23:05:09              ? proc [kibana]     at process._tickCallback (internal/process/next_tick.js:188:7)
23:05:09              ? proc [kibana]   log   [23:05:09.368] [debug][reporting][worker] PDF: Worker error: (jokms0g2037v4919626kr7c5)
23:05:09              ? proc [kibana]   log   [23:05:09.370] [esqueue][reporting][warn][worker] jokmrezw037v4919629x1fh8 - Failing job jokms0g2037v4919626kr7c5

@elasticmachine
Copy link
Contributor

💔 Build Failed

@tsullivan tsullivan added review and removed WIP Work in progress labels Nov 19, 2018
@@ -29,10 +29,6 @@ export default function ({ getService }) {
expect(usage.reporting.enabled).to.be(true);
});

Copy link
Contributor

Choose a reason for hiding this comment

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

:)

// "Kibana could not load correctly", etc
this.logger.error(`waitForSelector ${selector} failed on ${this.page.url()}`);
const pageText = await this.evaluate({
fn: () => document.querySelector('body')!.innerText,
Copy link
Contributor

Choose a reason for hiding this comment

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

You probably don't want the bang here:

fn: () => document.querySelector('body').innerText,

Copy link
Member Author

Choose a reason for hiding this comment

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

The ! is the "Non-null assertion operator" for Typescript to not fail compilation for the reason that the return from document.querySelector('body') is possibly null. It's not as safe as a guard, though. It's possible for querySelector to return null if an element isn't found, but for body I don't see it ever happening.

Copy link
Contributor

Choose a reason for hiding this comment

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

TIL! Does the TS compiler remove this when built? Reason I ask is because this function gets stringified and sent over WebSockets over to the browser... so if it doesn't it'll have issues running

Copy link
Contributor

@joelgriffith joelgriffith left a comment

Choose a reason for hiding this comment

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

I think there's a possible syntax error when exporting the HTML of the page (see my comment).

@elasticmachine
Copy link
Contributor

💚 Build Succeeded

@elasticmachine
Copy link
Contributor

💚 Build Succeeded

@tsullivan
Copy link
Member Author

Does the TS compiler remove this when built

Yes, it doesn't have any effect on the built JS, it's just a compile-time operator.

@tsullivan tsullivan merged commit 34d7a3b into elastic:master Nov 27, 2018
@tsullivan tsullivan deleted the reporting/logging-waitForSelector branch November 27, 2018 17:57
tsullivan added a commit to tsullivan/kibana that referenced this pull request Nov 27, 2018
* [Reporting] Better logging for waitForSelector failure

* break waitForSelector

* experimental changes

* cleanup/consistency

* fix some test report title strings

* test disable chromium

* roll back test code

* take out non-working phantom changes

* roll back disable chromium test

* allow logger to use curried tags

* temporarily re-do report failure-causing change for test

* replace newline with escaped for single log line

* undo test change

* remove obsolete test
tsullivan added a commit that referenced this pull request Nov 27, 2018
* [Reporting] Better logging for waitForSelector failure

* break waitForSelector

* experimental changes

* cleanup/consistency

* fix some test report title strings

* test disable chromium

* roll back test code

* take out non-working phantom changes

* roll back disable chromium test

* allow logger to use curried tags

* temporarily re-do report failure-causing change for test

* replace newline with escaped for single log line

* undo test change

* remove obsolete test
sebelga added a commit that referenced this pull request Nov 28, 2018
* [APM] Fix horizontal scrollbar being visible in windows 8.1 (#25988)

* [APM] Changed 'Response Time' to 'Duration' in transactions screens (#25990)

* translate InfraOps visualization component (Part 3) (#25213)

* translate InfraOps visualization component (Part 3 - part of folder components)

* update translation of Infra Ops vizualization component (Part 3)

* update translation of Infra Ops vizualization component (Part 3)

* change some ids and add pluralization

* update Infra Ops Part 3 - change some ids, change some intl.formatMessage() to <FormattedMessage> and directly wrap some classes by injectI18n()

* update Infra-III - add static to displayName

* [i18n] Translate Agg_types(part_3) (#26118)

* Translate agg_types - metrics

* Fix issues

* [ML] Aggregate anomalies table data using configured Kibana timezone (#26192)

* [ML] Aggregate anomalies table data using configured Kibana timezone

* [ML] Move dataFormatTz prop out of controller scope

* [ML] Fix alignment of filter icons in anomalies table (#26253)

* [ML] Fix alignment of filter icons in anomalies table

* [ML] Teak y position of icons in expanded row of table

* translate sample data (#26069)

translate sample data

* [ML] Wrap controller initialization in assertions. (#26265)

- The controller tests introduced in #25382 had a flaw: If a controller initialization would fail and throw an error, that test suite wouldn't be able to clean up any stubs. So tests using the same stubs would report and error because the stubs couldn't be wrapped again.
- This PR wraps every controller initialization inside an assertion and catches those errors properly as part of the test.

* [APM] fixes #20145 by displaying span.context.http.url in the span details flyout (#26238)

* Fix spaces license check (#26270)

## Summary

Allows the public spaces API to work with a gold license

Resolves #26271

* Job Info button in Reporting Listing (#25421)

* Job Info button in Reporting Listing

* use lodash directly

* start of flyout use

* description list in flyout

* capitalize

* undefined guard

* expire info on close

* add jest test

* better at error handling + messaging

* Add description for vis types (#26243)

* [migrations] Throw error if reindex task fails (#26062)

Signed-off-by: Tyler Smalley <[email protected]>

* [Reporting] Better logging for waitForSelector failure (#25762)

* [Reporting] Better logging for waitForSelector failure

* break waitForSelector

* experimental changes

* cleanup/consistency

* fix some test report title strings

* test disable chromium

* roll back test code

* take out non-working phantom changes

* roll back disable chromium test

* allow logger to use curried tags

* temporarily re-do report failure-causing change for test

* replace newline with escaped for single log line

* undo test change

* remove obsolete test

* [kbn/pm] allow packages to define extra paths to clean (#26132)

I noticed some discussion about how kbn clean should probably clear out the `.eslintcache` file, since it doesn't handle changes in related modules (for things like the import plugin) and it would be nice if `yarn kbn clean` took care of the issue. I figured it's not a bad idea, but adding `.eslintcache` directly to `@kbn/pm` felt wrong, so instead I've added another config options that can go in the package.json file, `clean.extraPatterns`. This array of patterns is passed into `del()` so that it can include things like negation.

As the name suggests this doesn't override the initial paths, just adds some extras that will be checked and cleared when `yarn kbn clean` is run.

* [config] fix logging.useUTC deprecation unset (#26053)

* Extend precommit hook script to support git GUI apps (#25883)

* feat(NA): extend support from precommit hook to git GUI apps.

* docs(NA): more descriptive error message.

* [DOCS] Clarify monitoring dependencies (#26229)

* apm: add ECS fields to index pattern (#26214)

* support standard license (#26294)

* [kbn-pm] update build

* [eslint] use disallow license header rule (#26309)

Fixes #26295

There are several places where we have accidentally added new license headers with linters but failed to remove old license headers manually. This prevents that by applying the an inverted version of the license headers rule that removed invalid license headers when files are moved.

* Bump node to 8.14.0 (#26313)

Signed-off-by: Tyler Smalley <[email protected]>

* Watch optimizer cache invalidation  (#24172)

* chore(NA): cherry pick work from spencer on impleting the cache invalidation system and merging it with current master.

* feat(NA): add support for dlls bundle into the cache state invalidation system.

* chore(NA): merge with master.

* feat(NA): first working version for the watch cache.

* feat(NA): added logger, correct cache delete and removed last todos.

* feat(NA): remove some useless features for the time being.

* refact(NA): just pass kibanaHapiServer.log function directly instead of an anonimous function that calls the kibanaHapiServer.log one.

* refact(NA): move everything to async.

* refact(NA): remove dll mentions.

* chore(NA): removed types/mkdirp as we dont use mkdirp into typescript.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
(Deprecated) Feature:Reporting Use Reporting:Screenshot, Reporting:CSV, or Reporting:Framework instead review v6.6.0 v7.0.0
Projects
None yet
Development

Successfully merging this pull request may close these issues.

3 participants