Closed
Bug 1591560
Opened 5 years ago
Closed 4 years ago
Intermittent Browsertime warm page loads failing on raptor-tp6-facebook
Categories
(Testing :: Raptor, defect, P3)
Tracking
(Not tracked)
RESOLVED
WORKSFORME
People
(Reporter: sparky, Assigned: sparky)
References
(Blocks 1 open bug)
Details
(Keywords: regression)
Currently browsertime warm page load tests are failing because of a failure in the facebook test:
[task 2019-10-25T18:36:28.005Z] 18:36:28 INFO - "xvfb-params": {
[task 2019-10-25T18:36:28.005Z] 18:36:28 INFO - "display": 99
[task 2019-10-25T18:36:28.005Z] 18:36:28 INFO - },
[task 2019-10-25T18:36:28.005Z] 18:36:28 INFO - "preURLDelay": 1500,
[task 2019-10-25T18:36:28.006Z] 18:36:28 INFO - "pre-url-delay": 1500,
[task 2019-10-25T18:36:28.006Z] 18:36:28 INFO - "silent": 0,
[task 2019-10-25T18:36:28.006Z] 18:36:28 INFO - "q": 0,
[task 2019-10-25T18:36:28.006Z] 18:36:28 INFO - "$0": "..\\fetches\\browsertime\\node_modules\\browsertime\\bin\\browsertime.js"
[task 2019-10-25T18:36:28.006Z] 18:36:28 INFO - }
[task 2019-10-25T18:36:28.011Z] 18:36:28 INFO - [2019-10-25 18:36:28] INFO: [browsertime] appConstants is a new-style script object.
[task 2019-10-25T18:36:28.029Z] 18:36:28 INFO - [2019-10-25 18:36:28] INFO: [browsertime] Running tests using Firefox - 1 iteration(s)
[task 2019-10-25T18:36:28.100Z] 18:36:28 INFO - 1572028588094 webdriver::command WARN You are using deprecated legacy session negotiation patterns (desiredCapabilities/requiredCapabilities), see https://developer.mozilla.org/en-US/docs/Web/WebDriver/Capabilities#Legacy
[task 2019-10-25T18:36:28.109Z] 18:36:28 INFO - 1572028588102 mozrunner::runner INFO Running command: "C:\\Users\\task_1572026697\\build\\application\\firefox\\firefox.exe" "-marionette" "-no-remote" "-foreground" "-profile" "C:\\Users\\task_1572026697\\AppData\\Local\\Temp\\rust_mozprofilee4Ac2z"
[task 2019-10-25T18:36:28.559Z] 18:36:28 INFO - 1572028588555 addons.webextension.screenshots@mozilla.org WARN Loading extension 'screenshots@mozilla.org': Reading manifest: Invalid extension permission: mozillaAddons
[task 2019-10-25T18:36:28.559Z] 18:36:28 INFO - 1572028588555 addons.webextension.screenshots@mozilla.org WARN Loading extension 'screenshots@mozilla.org': Reading manifest: Invalid extension permission: telemetry
[task 2019-10-25T18:36:28.559Z] 18:36:28 INFO - 1572028588555 addons.webextension.screenshots@mozilla.org WARN Loading extension 'screenshots@mozilla.org': Reading manifest: Invalid extension permission: resource://pdf.js/
[task 2019-10-25T18:36:28.559Z] 18:36:28 INFO - 1572028588555 addons.webextension.screenshots@mozilla.org WARN Loading extension 'screenshots@mozilla.org': Reading manifest: Invalid extension permission: about:reader*
[task 2019-10-25T18:36:29.832Z] 18:36:29 INFO - 1572028589829 Marionette INFO Listening on port 58675
[task 2019-10-25T18:36:30.353Z] 18:36:30 INFO - [2019-10-25 18:36:30] INFO: [browsertime] Starting a browsertime pageload
[task 2019-10-25T18:36:30.353Z] 18:36:30 INFO - [2019-10-25 18:36:30] INFO: [browsertime] Waiting for 5000 ms (foreground_delay)
[task 2019-10-25T18:36:35.354Z] 18:36:35 INFO - [2019-10-25 18:36:35] INFO: [browsertime] Navigating to about:blank
[task 2019-10-25T18:36:35.354Z] 18:36:35 INFO - [2019-10-25 18:36:35] INFO: [browsertime.command.measure] Navigating to url about:blank iteration 1
[task 2019-10-25T18:36:35.873Z] 18:36:35 INFO - [2019-10-25 18:36:35] DEBUG: [browsertime] Waiting for script pageCompleteCheck at most 300000 ms
[task 2019-10-25T18:36:35.873Z] 18:36:35 INFO - [2019-10-25 18:36:35] VERBOSE: [browsertime] Waiting for script
[task 2019-10-25T18:36:35.873Z] 18:36:35 INFO - return (function(waitTime) {
[task 2019-10-25T18:36:35.874Z] 18:36:35 INFO - try {
[task 2019-10-25T18:36:35.874Z] 18:36:35 INFO - var end = window.performance.timing.loadEventEnd;
[task 2019-10-25T18:36:35.874Z] 18:36:35 INFO - return (end > 0) && (Date.now() > end + waitTime);
[task 2019-10-25T18:36:35.874Z] 18:36:35 INFO - } catch(e) {
[task 2019-10-25T18:36:35.874Z] 18:36:35 INFO - return true;
[task 2019-10-25T18:36:35.874Z] 18:36:35 INFO - }
[task 2019-10-25T18:36:35.874Z] 18:36:35 INFO - })(arguments[arguments.length - 1]);
[task 2019-10-25T18:36:40.378Z] 18:36:40 INFO - [2019-10-25 18:36:40] INFO: [browsertime] Waiting for 30000 ms (post_startup_delay)
[task 2019-10-25T18:37:10.369Z] 18:37:10 INFO - [2019-10-25 18:37:10] INFO: [browsertime] Cycle 0, waiting for 1000 ms
[task 2019-10-25T18:37:11.370Z] 18:37:11 INFO - [2019-10-25 18:37:11] INFO: [browsertime] Cycle 0, starting the measure
[task 2019-10-25T18:37:11.370Z] 18:37:11 INFO - [2019-10-25 18:37:11] INFO: [browsertime.command.measure] Testing url https://www.facebook.com iteration 1
[task 2019-10-25T18:37:11.554Z] 18:37:11 INFO - console.timeStamp: "t_start"
[task 2019-10-25T18:37:11.999Z] 18:37:11 INFO - [2019-10-25 18:37:11] DEBUG: [browsertime] Waiting for script pageCompleteCheck at most 300000 ms
[task 2019-10-25T18:37:11.999Z] 18:37:11 INFO - [2019-10-25 18:37:11] VERBOSE: [browsertime] Waiting for script
[task 2019-10-25T18:37:11.999Z] 18:37:11 INFO - return (function(waitTime) {
[task 2019-10-25T18:37:11.999Z] 18:37:11 INFO - try {
[task 2019-10-25T18:37:11.999Z] 18:37:11 INFO - var end = window.performance.timing.loadEventEnd;
[task 2019-10-25T18:37:11.999Z] 18:37:11 INFO - return (end > 0) && (Date.now() > end + waitTime);
[task 2019-10-25T18:37:11.999Z] 18:37:11 INFO - } catch(e) {
[task 2019-10-25T18:37:11.999Z] 18:37:11 INFO - return true;
[task 2019-10-25T18:37:11.999Z] 18:37:11 INFO - }
[task 2019-10-25T18:37:12.000Z] 18:37:12 INFO - })(arguments[arguments.length - 1]);
[task 2019-10-25T18:37:12.342Z] 18:37:12 INFO - console.timeStamp: "t_domcontent"
[task 2019-10-25T18:37:12.342Z] 18:37:12 INFO - console.timeStamp: "t_tti"
[task 2019-10-25T18:37:12.524Z] 18:37:12 INFO - console.timeStamp: "t_prehooks"
[task 2019-10-25T18:37:12.524Z] 18:37:12 INFO - console.timeStamp: "t_hooks"
[task 2019-10-25T18:37:12.630Z] 18:37:12 INFO - console.error: "ErrorUtils caught an error: \"Tried to listen to element of type click from Error: Cannot listen to an unde...\". Subsequent errors won't be logged; see https://fburl.com/debugjs."
[task 2019-10-25T18:37:12.883Z] 18:37:12 INFO - console.log: "\n\n\n \n .d8888b. 888 888 \nd88P Y88b 888 888 \nY88b. 888 888 This is a browser feature intended for \n \"Y888b. 888888 .d88b. 88888b. 888 developers. If someone told you to copy-paste \n \"Y88b. 888 d88\"\"88b 888 \"88b 888 something here to enable a Facebook feature \n \"888 888 888 888 888 888 Y8P or \"hack\" someone's account, it is a \nY88b d88P Y88b. Y88..88P 888 d88P scam and will give them access to your \n \"Y8888P\" \"Y888 \"Y88P\" 88888P\" 888 Facebook account.\n 888 \n 888 \n 888 \n\nSee https://www.facebook.com/selfxss for more information.\n"
[task 2019-10-25T18:37:13.205Z] 18:37:13 INFO - console.timeStamp: "t_layout"
[task 2019-10-25T18:37:13.207Z] 18:37:13 INFO - console.timeStamp: "perf_trace {\"name\": \"e2e\", \"parent\": \"PageEvents.BIGPIPE_ONLOAD\"}"
[task 2019-10-25T18:37:13.245Z] 18:37:13 INFO - console.timeStamp: "t_paint"
In the end, no results are produced:
[task 2019-10-25T20:15:32.050Z] 20:15:32 INFO - perftest-results-handler Info: found browsertime results at C:\Users\task_1572031676\build\blobber_upload_dir\browsertime-results\raptor-tp6-facebook-firefox\browsertime.json
[task 2019-10-25T20:15:32.050Z] 20:15:32 INFO - perftest-results-handler Info: parsing results from browsertime json
[task 2019-10-25T20:15:32.055Z] 20:15:32 ERROR - Traceback (most recent call last):
[task 2019-10-25T20:15:32.055Z] 20:15:32 INFO - File "C:\Users\task_1572031676\build\tests\raptor\raptor\raptor.py", line 1530, in <module>
[task 2019-10-25T20:15:32.055Z] 20:15:32 INFO - main()
[task 2019-10-25T20:15:32.055Z] 20:15:32 INFO - File "C:\Users\task_1572031676\build\tests\raptor\raptor\raptor.py", line 1498, in main
[task 2019-10-25T20:15:32.055Z] 20:15:32 INFO - success = raptor.run_tests(raptor_test_list, raptor_test_names)
[task 2019-10-25T20:15:32.055Z] 20:15:32 INFO - File "C:\Users\task_1572031676\build\tests\raptor\raptor\raptor.py", line 214, in run_tests
[task 2019-10-25T20:15:32.055Z] 20:15:32 INFO - return self.process_results(tests, test_names)
[task 2019-10-25T20:15:32.055Z] 20:15:32 INFO - File "C:\Users\task_1572031676\build\tests\raptor\raptor\raptor.py", line 241, in process_results
[task 2019-10-25T20:15:32.056Z] 20:15:32 INFO - return self.results_handler.summarize_and_output(self.config, tests, test_names)
[task 2019-10-25T20:15:32.056Z] 20:15:32 INFO - File "C:\Users\task_1572031676\build\tests\raptor\raptor\results.py", line 386, in summarize_and_output
[task 2019-10-25T20:15:32.056Z] 20:15:32 INFO - for new_result in self.parse_browsertime_json(raw_btresults):
[task 2019-10-25T20:15:32.056Z] 20:15:32 INFO - File "C:\Users\task_1572031676\build\tests\raptor\raptor\results.py", line 320, in parse_browsertime_json
[task 2019-10-25T20:15:32.056Z] 20:15:32 INFO - raise ValueError("Browsertime produced no measurements.")
[task 2019-10-25T20:15:32.056Z] 20:15:32 INFO - ValueError: Browsertime produced no measurements.
[task 2019-10-25T20:15:32.082Z] 20:15:32 ERROR - Return code: 1
This failure shows two issues: (i) facebook pages are failing, and (ii) that we need to fail after parsing all available data not while we're parsing it so that we can still get data from the other tests when one of them fails.
|
Assignee | |
Updated•5 years ago
|
Summary: Browsertime warm page loads failing on raptor-tp6-facebook → Intermittent Browsertime warm page loads failing on raptor-tp6-facebook
|
||
Updated•5 years ago
|
Priority: -- → P1
|
|
||
Updated•5 years ago
|
Priority: P1 → P2
|
|
||
Updated•4 years ago
|
Blocks: browsertime-ci
Priority: P2 → P1
|
|
||
Comment 1•4 years ago
|
||
Hey :sparky would you mind checking to see if this intermittent still exists? Thanks!
Flags: needinfo?(gmierz2)
|
|
Assignee | |
Comment 2•4 years ago
|
||
I don't see it on mozilla-central but I'll make a try push for this bug and check it out to be sure it's gone. (Leaving the ni? open for myself).
|
||
Updated•4 years ago
|
Assignee: nobody → gmierz2
|
|
||
Comment 3•4 years ago
|
||
Hey :sparky, setting this to P2 since no activity for a few weeks but please reset as P1 when you resume this, thanks!
Priority: P1 → P2
|
|
Assignee | |
Comment 4•4 years ago
|
||
This failure still exists, but it's a permafail on mac: https://treeherder.mozilla.org/#/jobs?repo=try&tier=1%2C2%2C3&revision=60b3e9ad69816081f344ff8a5969601919442290
The same failure is also occurring here:
[task 2020-01-07T16:19:37.112Z] 16:19:37 INFO - console.error: "ErrorUtils caught an error: \"Tried to listen to element of type click from Error: Cannot listen to an unde...\". Subsequent errors won't be logged; see https://fburl.com/debugjs."
[task 2020-01-07T16:19:37.292Z] 16:19:37 INFO - console.log: "\n\n\n \n .d8888b. 888 888 \nd88P Y88b 888 888 \nY88b. 888 888 This is a browser feature intended for \n \"Y888b. 888888 .d88b. 88888b. 888 developers. If someone told you to copy-paste \n \"Y88b. 888 d88\"\"88b 888 \"88b 888 something here to enable a Facebook feature \n \"888 888 888 888 888 888 Y8P or \"hack\" someone's account, it is a \nY88b d88P Y88b. Y88..88P 888 d88P scam and will give them access to your \n \"Y8888P\" \"Y888 \"Y88P\" 88888P\" 888 Facebook account.\n 888 \n 888 \n 888 \n\nSee https://www.facebook.com/selfxss for more information.\n"
Flags: needinfo?(gmierz2)
|
||
Comment 5•4 years ago
|
||
Greg, are you still working on this bug? Does it have to be P2?
Flags: needinfo?(gmierz2)
|
|
Assignee | |
Comment 6•4 years ago
|
||
No, and I haven't seen this failure in a while so I'm going to mark this as resolved. Thanks for the ping!
Status: NEW → RESOLVED
Closed: 4 years ago
Flags: needinfo?(gmierz2)
Priority: P2 → P3
Resolution: --- → WORKSFORME
|
||
Comment 7•4 years ago
|
||
Bugbug thinks this bug is a regression, but please revert this change in case of error.
Keywords: regression
You need to log in
before you can comment on or make changes to this bug.
Description
•